You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/02/28 02:13:36 UTC
[JENKINS] Lucene-Solr-Tests-trunk-java7 - Build # 3770 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-java7/3770/
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:22940/pz_dvy/e/collection1skip list:[CloudJettyRunner [url=http://127.0.0.1:23778/pz_dvy/e/collection1], CloudJettyRunner [url=http://127.0.0.1:23778/pz_dvy/e/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:22940/pz_dvy/e/collection1skip list:[CloudJettyRunner [url=http://127.0.0.1:23778/pz_dvy/e/collection1], CloudJettyRunner [url=http://127.0.0.1:23778/pz_dvy/e/collection1]]
at __randomizedtesting.SeedInfo.seed([F281F5DD015F89B1:73677BC57600E98D]: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:805)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 9504 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 0 T3241 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /pz_dvy/e
[junit4:junit4] 2> 5 T3241 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1362013778479
[junit4:junit4] 2> 6 T3241 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 7 T3242 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 10 T3242 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 11 T3242 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 11 T3242 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 11 T3242 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 12 T3242 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 108 T3241 oasc.ZkTestServer.run start zk server on port:15182
[junit4:junit4] 2> 109 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@191f966f
[junit4:junit4] 2> 110 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 110 T3247 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 111 T3247 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 111 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:15183
[junit4:junit4] 2> 112 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:15183
[junit4:junit4] 2> 112 T3245 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 140 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f2360000 with negotiated timeout 10000 for client /140.211.11.196:15183
[junit4:junit4] 2> 140 T3247 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f2360000, negotiated timeout = 10000
[junit4:junit4] 2> 141 T3248 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@191f966f name:ZooKeeperConnection Watcher:127.0.0.1:15182 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 141 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 142 T3241 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 145 T3246 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d1e58f2360000
[junit4:junit4] 2> 146 T3248 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 146 T3241 oaz.ZooKeeper.close Session: 0x13d1e58f2360000 closed
[junit4:junit4] 2> 147 T3243 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:15183 which had sessionid 0x13d1e58f2360000
[junit4:junit4] 2> 147 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@ac9c954
[junit4:junit4] 2> 148 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 148 T3249 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 149 T3249 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 149 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:15184
[junit4:junit4] 2> 150 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:15184
[junit4:junit4] 2> 156 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f2360001 with negotiated timeout 10000 for client /140.211.11.196:15184
[junit4:junit4] 2> 156 T3249 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f2360001, negotiated timeout = 10000
[junit4:junit4] 2> 156 T3250 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ac9c954 name:ZooKeeperConnection Watcher:127.0.0.1:15182/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 156 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 157 T3241 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 162 T3241 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 170 T3241 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 173 T3241 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 176 T3241 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 176 T3241 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 191 T3241 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 193 T3241 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 297 T3241 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 298 T3241 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 302 T3241 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 303 T3241 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 306 T3241 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 306 T3241 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 315 T3241 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 316 T3241 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 319 T3241 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 320 T3241 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 323 T3241 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 324 T3241 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 328 T3241 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 329 T3241 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 332 T3246 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d1e58f2360001
[junit4:junit4] 2> 333 T3250 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 333 T3241 oaz.ZooKeeper.close Session: 0x13d1e58f2360001 closed
[junit4:junit4] 2> 334 T3243 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:15184 which had sessionid 0x13d1e58f2360001
[junit4:junit4] 2> 519 T3241 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 525 T3241 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:15185
[junit4:junit4] 2> 526 T3241 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 526 T3241 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 527 T3241 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362013778807
[junit4:junit4] 2> 527 T3241 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362013778807/solr.xml
[junit4:junit4] 2> 528 T3241 oasc.CoreContainer.<init> New CoreContainer 810161000
[junit4:junit4] 2> 529 T3241 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362013778807/'
[junit4:junit4] 2> 529 T3241 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362013778807/'
[junit4:junit4] 2> 632 T3241 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 633 T3241 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 633 T3241 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 634 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 634 T3241 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 635 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 635 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 636 T3241 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 636 T3241 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 637 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 659 T3241 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 678 T3241 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:15182/solr
[junit4:junit4] 2> 679 T3241 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 680 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@311b11b3
[junit4:junit4] 2> 681 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 681 T3260 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 682 T3260 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 683 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:15186
[junit4:junit4] 2> 683 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:15186
[junit4:junit4] 2> 685 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f2360002 with negotiated timeout 20000 for client /140.211.11.196:15186
[junit4:junit4] 2> 685 T3260 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f2360002, negotiated timeout = 20000
[junit4:junit4] 2> 686 T3261 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@311b11b3 name:ZooKeeperConnection Watcher:127.0.0.1:15182 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 686 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 687 T3246 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d1e58f2360002
[junit4:junit4] 2> 697 T3243 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:15186 which had sessionid 0x13d1e58f2360002
[junit4:junit4] 2> 697 T3261 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 697 T3241 oaz.ZooKeeper.close Session: 0x13d1e58f2360002 closed
[junit4:junit4] 2> 698 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 710 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@15cbd240
[junit4:junit4] 2> 712 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 712 T3262 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 713 T3262 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 713 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:15187
[junit4:junit4] 2> 713 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:15187
[junit4:junit4] 2> 715 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f2360003 with negotiated timeout 20000 for client /140.211.11.196:15187
[junit4:junit4] 2> 715 T3262 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f2360003, negotiated timeout = 20000
[junit4:junit4] 2> 715 T3263 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15cbd240 name:ZooKeeperConnection Watcher:127.0.0.1:15182/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 716 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 718 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 725 T3241 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 728 T3241 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:15185_pz_dvy%2Fe
[junit4:junit4] 2> 728 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:15185_pz_dvy%2Fe Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:15185_pz_dvy%2Fe
[junit4:junit4] 2> 729 T3241 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:15185_pz_dvy%2Fe
[junit4:junit4] 2> 738 T3241 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 751 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 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> 753 T3241 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 755 T3241 oasc.Overseer.start Overseer (id=89260934986858499-127.0.0.1:15185_pz_dvy%2Fe-n_0000000000) starting
[junit4:junit4] 2> 756 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 757 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 759 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 768 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 769 T3265 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 770 T3241 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 778 T3241 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 781 T3264 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 785 T3266 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362013778807/collection1
[junit4:junit4] 2> 785 T3266 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 786 T3266 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 786 T3266 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 788 T3266 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362013778807/collection1/'
[junit4:junit4] 2> 789 T3266 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1362013778807/collection1/lib/README' to classloader
[junit4:junit4] 2> 789 T3266 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1362013778807/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 840 T3266 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 899 T3266 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1000 T3266 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 1007 T3266 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 1642 T3266 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 1654 T3266 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1659 T3266 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1670 T3266 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1675 T3266 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1679 T3266 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1680 T3266 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 1681 T3266 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1362013778807/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data/
[junit4:junit4] 2> 1682 T3266 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@46961df6
[junit4:junit4] 2> 1682 T3266 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1683 T3266 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data forceNew:false
[junit4:junit4] 2> 1684 T3266 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data
[junit4:junit4] 2> 1684 T3266 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data/index/
[junit4:junit4] 2> 1685 T3266 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1685 T3266 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data/index forceNew:false
[junit4:junit4] 2> 1688 T3266 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@16851877 lockFactory=org.apache.lucene.store.NativeFSLockFactory@414751f9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 1689 T3266 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 1690 T3266 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data/index
[junit4:junit4] 2> 1692 T3266 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1692 T3266 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1693 T3266 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1693 T3266 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1694 T3266 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1694 T3266 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1695 T3266 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1695 T3266 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1696 T3266 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1708 T3266 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1714 T3266 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data
[junit4:junit4] 2> 1715 T3266 oass.SolrIndexSearcher.<init> Opening Searcher@4e77dd55 main
[junit4:junit4] 2> 1715 T3266 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data/tlog
[junit4:junit4] 2> 1716 T3266 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1716 T3266 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1720 T3267 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4e77dd55 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1722 T3266 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1722 T3266 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1723 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 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> 2284 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2284 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[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:15185_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:15185/pz_dvy/e"}
[junit4:junit4] 2> 2285 T3264 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2285 T3264 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 2285 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 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> 2302 T3263 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> 2762 T3266 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2762 T3266 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:15185/pz_dvy/e collection:control_collection shard:shard1
[junit4:junit4] 2> 2763 T3266 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2777 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 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> 2778 T3266 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2779 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2780 T3266 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2781 T3266 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2781 T3266 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:15185/pz_dvy/e/collection1/
[junit4:junit4] 2> 2781 T3266 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2782 T3266 oasc.SyncStrategy.syncToMe http://127.0.0.1:15185/pz_dvy/e/collection1/ has no replicas
[junit4:junit4] 2> 2782 T3266 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:15185/pz_dvy/e/collection1/
[junit4:junit4] 2> 2782 T3266 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2785 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3805 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3823 T3263 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> 3858 T3266 oasc.ZkController.register We are http://127.0.0.1:15185/pz_dvy/e/collection1/ and leader is http://127.0.0.1:15185/pz_dvy/e/collection1/
[junit4:junit4] 2> 3858 T3266 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:15185/pz_dvy/e
[junit4:junit4] 2> 3859 T3266 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3859 T3266 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3860 T3266 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3863 T3266 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3864 T3241 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3865 T3241 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3866 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3886 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3888 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@6d9a6073
[junit4:junit4] 2> 3889 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3890 T3268 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3890 T3268 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 3891 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:15193
[junit4:junit4] 2> 3891 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:15193
[junit4:junit4] 2> 3893 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f2360004 with negotiated timeout 10000 for client /140.211.11.196:15193
[junit4:junit4] 2> 3893 T3268 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f2360004, negotiated timeout = 10000
[junit4:junit4] 2> 3894 T3269 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6d9a6073 name:ZooKeeperConnection Watcher:127.0.0.1:15182/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3894 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3895 T3241 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3897 T3241 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 4101 T3241 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 4105 T3241 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:15194
[junit4:junit4] 2> 4106 T3241 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 4107 T3241 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 4107 T3241 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362013782370
[junit4:junit4] 2> 4108 T3241 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362013782370/solr.xml
[junit4:junit4] 2> 4109 T3241 oasc.CoreContainer.<init> New CoreContainer 2015539020
[junit4:junit4] 2> 4109 T3241 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362013782370/'
[junit4:junit4] 2> 4110 T3241 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362013782370/'
[junit4:junit4] 2> 4191 T3241 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 4193 T3241 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 4193 T3241 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 4194 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 4195 T3241 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 4195 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 4196 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 4197 T3241 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 4197 T3241 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 4198 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 4226 T3241 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 4247 T3241 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:15182/solr
[junit4:junit4] 2> 4248 T3241 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 4249 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@588cb166
[junit4:junit4] 2> 4250 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4250 T3279 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4251 T3279 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 4252 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:15202
[junit4:junit4] 2> 4252 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:15202
[junit4:junit4] 2> 4257 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f2360005 with negotiated timeout 20000 for client /140.211.11.196:15202
[junit4:junit4] 2> 4257 T3279 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f2360005, negotiated timeout = 20000
[junit4:junit4] 2> 4257 T3280 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@588cb166 name:ZooKeeperConnection Watcher:127.0.0.1:15182 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4257 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4258 T3246 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d1e58f2360005
[junit4:junit4] 2> 4276 T3280 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 4276 T3243 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:15202 which had sessionid 0x13d1e58f2360005
[junit4:junit4] 2> 4276 T3241 oaz.ZooKeeper.close Session: 0x13d1e58f2360005 closed
[junit4:junit4] 2> 4277 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 4290 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@3976238
[junit4:junit4] 2> 4291 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 4291 T3281 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 4292 T3281 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 4292 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:15203
[junit4:junit4] 2> 4293 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:15203
[junit4:junit4] 2> 4295 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f2360006 with negotiated timeout 20000 for client /140.211.11.196:15203
[junit4:junit4] 2> 4295 T3281 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f2360006, negotiated timeout = 20000
[junit4:junit4] 2> 4295 T3282 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3976238 name:ZooKeeperConnection Watcher:127.0.0.1:15182/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 4295 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 4296 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4335 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 4337 T3241 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 5330 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 5331 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[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:15185_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:15185/pz_dvy/e"}
[junit4:junit4] 2> 5348 T3269 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> 5348 T3263 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> 5348 T3282 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> 5348 T3241 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:15194_pz_dvy%2Fe
[junit4:junit4] 2> 5349 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360006 type:delete cxid:0xb zxid:0x4e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:15194_pz_dvy%2Fe Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:15194_pz_dvy%2Fe
[junit4:junit4] 2> 5350 T3241 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:15194_pz_dvy%2Fe
[junit4:junit4] 2> 5353 T3269 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> 5353 T3263 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> 5353 T3282 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5353 T3282 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> 5354 T3263 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5354 T3269 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 5367 T3283 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362013782370/collection1
[junit4:junit4] 2> 5367 T3283 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 5368 T3283 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 5368 T3283 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 5369 T3283 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362013782370/collection1/'
[junit4:junit4] 2> 5370 T3283 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1362013782370/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 5371 T3283 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1362013782370/collection1/lib/README' to classloader
[junit4:junit4] 2> 5422 T3283 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 5481 T3283 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 5582 T3283 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 5588 T3283 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 6227 T3283 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 6238 T3283 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 6242 T3283 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 6254 T3283 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 6258 T3283 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 6262 T3283 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 6264 T3283 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 6265 T3283 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1362013782370/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/
[junit4:junit4] 2> 6265 T3283 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@46961df6
[junit4:junit4] 2> 6265 T3283 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 6266 T3283 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1 forceNew:false
[junit4:junit4] 2> 6267 T3283 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1
[junit4:junit4] 2> 6267 T3283 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/index/
[junit4:junit4] 2> 6268 T3283 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 6268 T3283 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/index forceNew:false
[junit4:junit4] 2> 6271 T3283 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 6271 T3283 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 6272 T3283 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/index
[junit4:junit4] 2> 6274 T3283 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 6275 T3283 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 6275 T3283 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 6276 T3283 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 6276 T3283 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 6277 T3283 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 6277 T3283 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 6278 T3283 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 6278 T3283 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 6290 T3283 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 6296 T3283 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1
[junit4:junit4] 2> 6296 T3283 oass.SolrIndexSearcher.<init> Opening Searcher@7b12facf main
[junit4:junit4] 2> 6297 T3283 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/tlog
[junit4:junit4] 2> 6297 T3283 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 6298 T3283 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 6302 T3284 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7b12facf main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 6304 T3283 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 6304 T3283 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6853 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6854 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[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:15194_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:15194/pz_dvy/e"}
[junit4:junit4] 2> 6854 T3264 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 6854 T3264 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6871 T3263 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> 6871 T3282 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> 6871 T3269 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> 7308 T3283 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 7308 T3283 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:15194/pz_dvy/e collection:collection1 shard:shard1
[junit4:junit4] 2> 7309 T3283 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 7323 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360006 type:delete cxid:0x48 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 7324 T3283 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 7325 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360006 type:create cxid:0x49 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7335 T3283 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 7335 T3283 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 7335 T3283 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:15194/pz_dvy/e/collection1/
[junit4:junit4] 2> 7336 T3283 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 7336 T3283 oasc.SyncStrategy.syncToMe http://127.0.0.1:15194/pz_dvy/e/collection1/ has no replicas
[junit4:junit4] 2> 7336 T3283 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:15194/pz_dvy/e/collection1/
[junit4:junit4] 2> 7336 T3283 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 7340 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360006 type:create cxid:0x53 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8375 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8417 T3263 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> 8417 T3282 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> 8417 T3269 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> 8464 T3283 oasc.ZkController.register We are http://127.0.0.1:15194/pz_dvy/e/collection1/ and leader is http://127.0.0.1:15194/pz_dvy/e/collection1/
[junit4:junit4] 2> 8464 T3283 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:15194/pz_dvy/e
[junit4:junit4] 2> 8464 T3283 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 8464 T3283 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 8465 T3283 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 8466 T3283 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 8467 T3241 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 8468 T3241 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 8468 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 8657 T3241 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 8661 T3241 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:22940
[junit4:junit4] 2> 8662 T3241 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 8662 T3241 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 8663 T3241 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362013786955
[junit4:junit4] 2> 8663 T3241 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362013786955/solr.xml
[junit4:junit4] 2> 8664 T3241 oasc.CoreContainer.<init> New CoreContainer 1998614857
[junit4:junit4] 2> 8665 T3241 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362013786955/'
[junit4:junit4] 2> 8665 T3241 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362013786955/'
[junit4:junit4] 2> 8725 T3241 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 8726 T3241 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 8727 T3241 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 8727 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 8728 T3241 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 8728 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 8729 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 8729 T3241 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 8730 T3241 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 8730 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 8750 T3241 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 8770 T3241 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:15182/solr
[junit4:junit4] 2> 8770 T3241 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 8771 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@2ab1d346
[junit4:junit4] 2> 8772 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8773 T3294 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8774 T3294 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 8774 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:58307
[junit4:junit4] 2> 8774 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:58307
[junit4:junit4] 2> 8778 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f2360007 with negotiated timeout 20000 for client /140.211.11.196:58307
[junit4:junit4] 2> 8778 T3294 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f2360007, negotiated timeout = 20000
[junit4:junit4] 2> 8778 T3295 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ab1d346 name:ZooKeeperConnection Watcher:127.0.0.1:15182 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8778 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8779 T3246 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d1e58f2360007
[junit4:junit4] 2> 8796 T3295 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 8796 T3243 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:58307 which had sessionid 0x13d1e58f2360007
[junit4:junit4] 2> 8796 T3241 oaz.ZooKeeper.close Session: 0x13d1e58f2360007 closed
[junit4:junit4] 2> 8797 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 8807 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@d6a9de7
[junit4:junit4] 2> 8808 T3296 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 8808 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 8809 T3296 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 8809 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:51876
[junit4:junit4] 2> 8809 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:51876
[junit4:junit4] 2> 8811 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f2360008 with negotiated timeout 20000 for client /140.211.11.196:51876
[junit4:junit4] 2> 8811 T3296 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f2360008, negotiated timeout = 20000
[junit4:junit4] 2> 8811 T3297 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d6a9de7 name:ZooKeeperConnection Watcher:127.0.0.1:15182/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 8811 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8812 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8814 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8821 T3241 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9823 T3241 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:22940_pz_dvy%2Fe
[junit4:junit4] 2> 9824 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f2360008 type:delete cxid:0x9 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:22940_pz_dvy%2Fe Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:22940_pz_dvy%2Fe
[junit4:junit4] 2> 9838 T3241 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:22940_pz_dvy%2Fe
[junit4:junit4] 2> 9840 T3269 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> 9840 T3263 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> 9840 T3282 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9840 T3297 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9841 T3282 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> 9850 T3269 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9850 T3263 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9856 T3298 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362013786955/collection1
[junit4:junit4] 2> 9856 T3298 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9857 T3298 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9857 T3298 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9858 T3298 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362013786955/collection1/'
[junit4:junit4] 2> 9860 T3298 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1362013786955/collection1/lib/README' to classloader
[junit4:junit4] 2> 9860 T3298 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1362013786955/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9910 T3298 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 9931 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9932 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[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:15194_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:15194/pz_dvy/e"}
[junit4:junit4] 2> 9945 T3297 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 9945 T3263 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 9945 T3269 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 9945 T3282 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> 9970 T3298 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 10071 T3298 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 10077 T3298 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 10708 T3298 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 10720 T3298 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 10724 T3298 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 10736 T3298 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10740 T3298 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 10745 T3298 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10745 T3298 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 10746 T3298 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1362013786955/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/
[junit4:junit4] 2> 10747 T3298 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@46961df6
[junit4:junit4] 2> 10747 T3298 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 10749 T3298 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2 forceNew:false
[junit4:junit4] 2> 10749 T3298 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2
[junit4:junit4] 2> 10749 T3298 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index/
[junit4:junit4] 2> 10750 T3298 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 10750 T3298 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index forceNew:false
[junit4:junit4] 2> 10753 T3298 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@2a93b3db lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a77a832),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 10753 T3298 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 10754 T3298 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index
[junit4:junit4] 2> 10756 T3298 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 10757 T3298 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 10757 T3298 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 10758 T3298 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 10759 T3298 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 10759 T3298 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 10759 T3298 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 10760 T3298 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 10760 T3298 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 10772 T3298 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 10777 T3298 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2
[junit4:junit4] 2> 10778 T3298 oass.SolrIndexSearcher.<init> Opening Searcher@476bd567 main
[junit4:junit4] 2> 10778 T3298 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/tlog
[junit4:junit4] 2> 10779 T3298 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 10779 T3298 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 10784 T3299 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@476bd567 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 10786 T3298 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 10787 T3298 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11449 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11450 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:22940_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:22940/pz_dvy/e"}
[junit4:junit4] 2> 11450 T3264 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 11450 T3264 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 11477 T3263 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> 11477 T3297 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> 11477 T3269 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> 11477 T3282 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> 11814 T3298 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11814 T3298 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:22940/pz_dvy/e collection:collection1 shard:shard1
[junit4:junit4] 2> 11817 T3298 oasc.ZkController.register We are http://127.0.0.1:22940/pz_dvy/e/collection1/ and leader is http://127.0.0.1:15194/pz_dvy/e/collection1/
[junit4:junit4] 2> 11817 T3298 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:22940/pz_dvy/e
[junit4:junit4] 2> 11817 T3298 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 11817 T3298 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C165 name=collection1 org.apache.solr.core.SolrCore@4e845c08 url=http://127.0.0.1:22940/pz_dvy/e/collection1 node=127.0.0.1:22940_pz_dvy%2Fe C165_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:22940_pz_dvy%2Fe, base_url=http://127.0.0.1:22940/pz_dvy/e}
[junit4:junit4] 2> 11819 T3300 C165 P22940 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 11819 T3298 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 11820 T3300 C165 P22940 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 11820 T3300 C165 P22940 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 11820 T3300 C165 P22940 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 11820 T3241 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 11821 T3241 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 11821 T3300 C165 P22940 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 11822 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 12018 T3241 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 12022 T3241 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:31879
[junit4:junit4] 2> 12023 T3241 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 12023 T3241 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 12024 T3241 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362013790315
[junit4:junit4] 2> 12024 T3241 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362013790315/solr.xml
[junit4:junit4] 2> 12025 T3241 oasc.CoreContainer.<init> New CoreContainer 728702851
[junit4:junit4] 2> 12025 T3241 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362013790315/'
[junit4:junit4] 2> 12026 T3241 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362013790315/'
[junit4:junit4] 2> 12086 T3241 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 12087 T3241 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 12087 T3241 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 12088 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 12088 T3241 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 12089 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 12089 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 12090 T3241 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 12090 T3241 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 12091 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 12111 T3241 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 12130 T3241 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:15182/solr
[junit4:junit4] 2> 12131 T3241 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 12131 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1eaaf38d
[junit4:junit4] 2> 12132 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 12133 T3310 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 12134 T3310 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 12134 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:26583
[junit4:junit4] 2> 12135 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:26583
[junit4:junit4] 2> 12137 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f2360009 with negotiated timeout 20000 for client /140.211.11.196:26583
[junit4:junit4] 2> 12137 T3310 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f2360009, negotiated timeout = 20000
[junit4:junit4] 2> 12137 T3311 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1eaaf38d name:ZooKeeperConnection Watcher:127.0.0.1:15182 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 12137 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 12138 T3246 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d1e58f2360009
[junit4:junit4] 2> 12150 T3311 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 12151 T3243 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:26583 which had sessionid 0x13d1e58f2360009
[junit4:junit4] 2> 12150 T3241 oaz.ZooKeeper.close Session: 0x13d1e58f2360009 closed
[junit4:junit4] 2> 12151 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 12161 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@2cfd2ee5
[junit4:junit4] 2> 12163 T3312 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 12162 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 12163 T3312 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 12163 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:22135
[junit4:junit4] 2> 12164 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:22135
[junit4:junit4] 2> 12165 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f236000a with negotiated timeout 20000 for client /140.211.11.196:22135
[junit4:junit4] 2> 12165 T3312 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f236000a, negotiated timeout = 20000
[junit4:junit4] 2> 12165 T3313 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2cfd2ee5 name:ZooKeeperConnection Watcher:127.0.0.1:15182/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 12166 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 12167 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f236000a type:create cxid:0x1 zxid:0x80 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12168 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f236000a type:create cxid:0x2 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12175 T3241 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 12981 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12982 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:22940_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:22940/pz_dvy/e"}
[junit4:junit4] 2> 12996 T3313 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> 12996 T3282 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> 12996 T3297 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> 12996 T3263 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> 12996 T3269 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> 13178 T3241 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:31879_pz_dvy%2Fe
[junit4:junit4] 2> 13179 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f236000a type:delete cxid:0xb zxid:0x86 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:31879_pz_dvy%2Fe Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:31879_pz_dvy%2Fe
[junit4:junit4] 2> 13180 T3241 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:31879_pz_dvy%2Fe
[junit4:junit4] 2> 13182 T3313 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> 13182 T3297 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> 13182 T3282 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13182 T3263 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> 13182 T3269 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> 13183 T3282 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> 13192 T3313 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13192 T3263 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13192 T3297 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13192 T3269 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13198 T3314 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362013790315/collection1
[junit4:junit4] 2> 13198 T3314 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 13199 T3314 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 13199 T3314 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 13200 T3314 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362013790315/collection1/'
[junit4:junit4] 2> 13201 T3314 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1362013790315/collection1/lib/README' to classloader
[junit4:junit4] 2> 13202 T3314 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1362013790315/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 13252 T3314 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 13311 T3314 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 13412 T3314 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 13418 T3314 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 14048 T3314 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 14061 T3314 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 14065 T3314 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 14077 T3314 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 14081 T3314 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 14086 T3314 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 14087 T3314 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 14088 T3314 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1362013790315/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/
[junit4:junit4] 2> 14088 T3314 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@46961df6
[junit4:junit4] 2> 14089 T3314 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 14090 T3314 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3 forceNew:false
[junit4:junit4] 2> 14090 T3314 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3
[junit4:junit4] 2> 14090 T3314 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index/
[junit4:junit4] 2> 14091 T3314 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 14092 T3314 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index forceNew:false
[junit4:junit4] 2> 14094 T3314 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5f71dac0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ecc6865),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 14095 T3314 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 14095 T3314 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index
[junit4:junit4] 2> 14098 T3314 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 14098 T3314 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 14099 T3314 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 14100 T3314 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 14100 T3314 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 14101 T3314 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 14101 T3314 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 14102 T3314 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 14102 T3314 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 14115 T3314 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 14121 T3314 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3
[junit4:junit4] 2> 14121 T3314 oass.SolrIndexSearcher.<init> Opening Searcher@421d3a58 main
[junit4:junit4] 2> 14122 T3314 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/tlog
[junit4:junit4] 2> 14122 T3314 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 14123 T3314 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 14127 T3315 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@421d3a58 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 14129 T3314 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 14130 T3314 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 14500 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 14501 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:31879_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31879/pz_dvy/e"}
[junit4:junit4] 2> 14501 T3264 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 14501 T3264 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 14518 T3269 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> 14518 T3313 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> 14518 T3263 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> 14518 T3297 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> 14518 T3282 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> 15142 T3314 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 15142 T3314 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:31879/pz_dvy/e collection:collection1 shard:shard1
[junit4:junit4] 2> 15145 T3314 oasc.ZkController.register We are http://127.0.0.1:31879/pz_dvy/e/collection1/ and leader is http://127.0.0.1:15194/pz_dvy/e/collection1/
[junit4:junit4] 2> 15145 T3314 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:31879/pz_dvy/e
[junit4:junit4] 2> 15145 T3314 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 15146 T3314 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C166 name=collection1 org.apache.solr.core.SolrCore@34559bbf url=http://127.0.0.1:31879/pz_dvy/e/collection1 node=127.0.0.1:31879_pz_dvy%2Fe C166_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:31879_pz_dvy%2Fe, base_url=http://127.0.0.1:31879/pz_dvy/e}
[junit4:junit4] 2> 15147 T3316 C166 P31879 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 15147 T3314 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15148 T3316 C166 P31879 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 15148 T3316 C166 P31879 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 15148 T3316 C166 P31879 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15148 T3241 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 15149 T3241 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 15150 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15237 T3316 C166 P31879 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15341 T3241 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 15344 T3241 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:23778
[junit4:junit4] 2> 15345 T3241 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 15345 T3241 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 15346 T3241 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362013793637
[junit4:junit4] 2> 15346 T3241 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362013793637/solr.xml
[junit4:junit4] 2> 15347 T3241 oasc.CoreContainer.<init> New CoreContainer 538544628
[junit4:junit4] 2> 15347 T3241 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362013793637/'
[junit4:junit4] 2> 15348 T3241 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362013793637/'
[junit4:junit4] 2> 15415 T3241 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 15416 T3241 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 15417 T3241 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 15417 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 15418 T3241 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 15418 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 15419 T3241 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 15419 T3241 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 15420 T3241 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 15420 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 15442 T3241 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 15461 T3241 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:15182/solr
[junit4:junit4] 2> 15462 T3241 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 15463 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@6a285fcc
[junit4:junit4] 2> 15464 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15464 T3326 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 15465 T3326 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 15466 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:22711
[junit4:junit4] 2> 15466 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:22711
[junit4:junit4] 2> 15468 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f236000b with negotiated timeout 20000 for client /140.211.11.196:22711
[junit4:junit4] 2> 15468 T3326 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f236000b, negotiated timeout = 20000
[junit4:junit4] 2> 15468 T3327 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6a285fcc name:ZooKeeperConnection Watcher:127.0.0.1:15182 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15469 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15470 T3246 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d1e58f236000b
[junit4:junit4] 2> 15477 T3327 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 15477 T3243 oazs.NIOServerCnxn.closeSock Closed socket connection for client /140.211.11.196:22711 which had sessionid 0x13d1e58f236000b
[junit4:junit4] 2> 15477 T3241 oaz.ZooKeeper.close Session: 0x13d1e58f236000b closed
[junit4:junit4] 2> 15477 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 15489 T3241 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:15182/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@7118334a
[junit4:junit4] 2> 15490 T3241 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15490 T3328 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost/127.0.0.1:15182. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 15491 T3328 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost/127.0.0.1:15182, initiating session
[junit4:junit4] 2> 15491 T3243 oazs.NIOServerCnxnFactory.run Accepted socket connection from /140.211.11.196:56420
[junit4:junit4] 2> 15492 T3243 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /140.211.11.196:56420
[junit4:junit4] 2> 15493 T3245 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d1e58f236000c with negotiated timeout 20000 for client /140.211.11.196:56420
[junit4:junit4] 2> 15493 T3328 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost/127.0.0.1:15182, sessionid = 0x13d1e58f236000c, negotiated timeout = 20000
[junit4:junit4] 2> 15493 T3329 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7118334a name:ZooKeeperConnection Watcher:127.0.0.1:15182/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15494 T3241 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15494 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f236000c type:create cxid:0x1 zxid:0x93 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 15496 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f236000c type:create cxid:0x2 zxid:0x94 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 15505 T3241 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> C165_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:22940_pz_dvy%2Fe, base_url=http://127.0.0.1:22940/pz_dvy/e}
[junit4:junit4] 2> 15847 T3300 C165 P22940 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:15194/pz_dvy/e/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 15847 T3300 C165 P22940 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:22940/pz_dvy/e START replicas=[http://127.0.0.1:15194/pz_dvy/e/collection1/] nUpdates=100
[junit4:junit4] 2> 15847 T3300 C165 P22940 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 15849 T3300 C165 P22940 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 15849 T3300 C165 P22940 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 15849 T3300 C165 P22940 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 15849 T3300 C165 P22940 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 15850 T3300 C165 P22940 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:15194/pz_dvy/e/collection1/. core=collection1
[junit4:junit4] 2> 15850 T3300 C165 P22940 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C167 name=collection1 org.apache.solr.core.SolrCore@9fe11c7 url=http://127.0.0.1:15194/pz_dvy/e/collection1 node=127.0.0.1:15194_pz_dvy%2Fe C167_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:15194_pz_dvy%2Fe, base_url=http://127.0.0.1:15194/pz_dvy/e, leader=true}
[junit4:junit4] 2> 15856 T3274 C167 P15194 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 15863 T3275 C167 P15194 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 15863 T3275 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1
[junit4:junit4] 2> 15865 T3275 C167 P15194 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 15866 T3275 C167 P15194 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 15867 T3275 C167 P15194 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15867 T3275 C167 P15194 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15868 T3275 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1
[junit4:junit4] 2> 15868 T3275 C167 P15194 oass.SolrIndexSearcher.<init> Opening Searcher@661a66b realtime
[junit4:junit4] 2> 15869 T3275 C167 P15194 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 15869 T3275 C167 P15194 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 15870 T3300 C165 P22940 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15870 T3300 C165 P22940 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 15873 T3276 C167 P15194 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 15873 T3276 C167 P15194 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 15874 T3300 C165 P22940 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 15874 T3300 C165 P22940 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 15874 T3300 C165 P22940 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 15876 T3276 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1
[junit4:junit4] 2> 15877 T3276 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/index
[junit4:junit4] 2> 15877 T3276 C167 P15194 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 15878 T3300 C165 P22940 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 15879 T3300 C165 P22940 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index.20130227190954351 forceNew:false
[junit4:junit4] 2> 15879 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2
[junit4:junit4] 2> 15880 T3300 C165 P22940 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@702ee8e lockFactory=org.apache.lucene.store.NativeFSLockFactory@f6ed9a1) fullCopy=true
[junit4:junit4] 2> 15882 T3276 C167 P15194 REQ /replication {file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 15883 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index
[junit4:junit4] 2> 15883 T3300 C165 P22940 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 15884 T3300 C165 P22940 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130227190954351
[junit4:junit4] 2> 15884 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2
[junit4:junit4] 2> 15885 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2
[junit4:junit4] 2> 15885 T3300 C165 P22940 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index/ new=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index.20130227190954351
[junit4:junit4] 2> 15887 T3300 C165 P22940 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@702ee8e lockFactory=org.apache.lucene.store.NativeFSLockFactory@f6ed9a1),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15887 T3300 C165 P22940 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15888 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2
[junit4:junit4] 2> 15888 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2
[junit4:junit4] 2> 15888 T3300 C165 P22940 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 15889 T3300 C165 P22940 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 15889 T3300 C165 P22940 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 15889 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index.20130227190954351
[junit4:junit4] 2> 15890 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2
[junit4:junit4] 2> 15891 T3300 C165 P22940 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@702ee8e lockFactory=org.apache.lucene.store.NativeFSLockFactory@f6ed9a1),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 15892 T3300 C165 P22940 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 15892 T3300 C165 P22940 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 15892 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2
[junit4:junit4] 2> 15893 T3300 C165 P22940 oass.SolrIndexSearcher.<init> Opening Searcher@999b6c4 main
[junit4:junit4] 2> 15894 T3299 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@999b6c4 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 15894 T3299 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index
[junit4:junit4] 2> 15894 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index.20130227190954351
[junit4:junit4] 2> 15895 T3300 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index
[junit4:junit4] 2> 15895 T3300 C165 P22940 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 15895 T3300 C165 P22940 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 15895 T3300 C165 P22940 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 15896 T3300 C165 P22940 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15897 T3300 C165 P22940 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 16023 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16023 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:31879_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31879/pz_dvy/e"}
[junit4:junit4] 2> 16027 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[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:22940_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:22940/pz_dvy/e"}
[junit4:junit4] 2> 16038 T3263 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> 16038 T3329 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> 16039 T3313 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> 16038 T3297 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> 16038 T3269 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> 16038 T3282 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> 16508 T3241 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:23778_pz_dvy%2Fe
[junit4:junit4] 2> 16509 T3246 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d1e58f236000c type:delete cxid:0xb zxid:0x9d txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:23778_pz_dvy%2Fe Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:23778_pz_dvy%2Fe
[junit4:junit4] 2> 16510 T3241 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:23778_pz_dvy%2Fe
[junit4:junit4] 2> 16512 T3269 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> 16512 T3313 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> 16512 T3263 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> 16512 T3297 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> 16513 T3329 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16513 T3282 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16514 T3329 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> 16514 T3282 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> 16514 T3269 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16522 T3313 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16522 T3263 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16522 T3297 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 16531 T3332 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362013793637/collection1
[junit4:junit4] 2> 16531 T3332 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 16532 T3332 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 16532 T3332 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 16533 T3332 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362013793637/collection1/'
[junit4:junit4] 2> 16534 T3332 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1362013793637/collection1/lib/README' to classloader
[junit4:junit4] 2> 16535 T3332 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1362013793637/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 16609 T3332 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 16668 T3332 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 16769 T3332 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 16776 T3332 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 17405 T3332 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 17418 T3332 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 17422 T3332 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 17433 T3332 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 17438 T3332 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 17442 T3332 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 17443 T3332 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 17444 T3332 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1362013793637/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/
[junit4:junit4] 2> 17445 T3332 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@46961df6
[junit4:junit4] 2> 17445 T3332 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 17446 T3332 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4 forceNew:false
[junit4:junit4] 2> 17447 T3332 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 17447 T3332 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index/
[junit4:junit4] 2> 17447 T3332 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 17448 T3332 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index forceNew:false
[junit4:junit4] 2> 17451 T3332 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@7a91ffba lockFactory=org.apache.lucene.store.NativeFSLockFactory@6cfd4699),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 17451 T3332 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 17452 T3332 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index
[junit4:junit4] 2> 17455 T3332 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 17455 T3332 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 17456 T3332 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 17456 T3332 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 17457 T3332 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 17457 T3332 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 17458 T3332 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 17458 T3332 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 17459 T3332 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 17471 T3332 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 17477 T3332 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 17478 T3332 oass.SolrIndexSearcher.<init> Opening Searcher@439f5bf3 main
[junit4:junit4] 2> 17478 T3332 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/tlog
[junit4:junit4] 2> 17479 T3332 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 17479 T3332 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 17484 T3333 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@439f5bf3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 17486 T3332 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 17487 T3332 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 17551 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 17551 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:23778_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:23778/pz_dvy/e"}
[junit4:junit4] 2> 17552 T3264 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 17552 T3264 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 17565 T3282 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> 17565 T3263 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> 17565 T3269 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> 17565 T3297 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> 17565 T3313 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> 17565 T3329 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> C166_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:31879_pz_dvy%2Fe, base_url=http://127.0.0.1:31879/pz_dvy/e}
[junit4:junit4] 2> 18249 T3316 C166 P31879 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:15194/pz_dvy/e/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 18249 T3316 C166 P31879 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:31879/pz_dvy/e START replicas=[http://127.0.0.1:15194/pz_dvy/e/collection1/] nUpdates=100
[junit4:junit4] 2> 18249 T3316 C166 P31879 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 18250 T3316 C166 P31879 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 18250 T3316 C166 P31879 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 18250 T3316 C166 P31879 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 18250 T3316 C166 P31879 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 18250 T3316 C166 P31879 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:15194/pz_dvy/e/collection1/. core=collection1
[junit4:junit4] 2> 18251 T3316 C166 P31879 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18252 T3274 C167 P15194 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 18266 T3277 C167 P15194 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 18268 T3277 C167 P15194 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18268 T3277 C167 P15194 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18269 T3277 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1
[junit4:junit4] 2> 18269 T3277 C167 P15194 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 18270 T3277 C167 P15194 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 18271 T3316 C166 P31879 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 18271 T3316 C166 P31879 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 18273 T3276 C167 P15194 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 18274 T3316 C166 P31879 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 18274 T3316 C166 P31879 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 18274 T3316 C166 P31879 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 18277 T3276 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1
[junit4:junit4] 2> 18277 T3276 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/index
[junit4:junit4] 2> 18278 T3276 C167 P15194 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 18279 T3316 C166 P31879 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 18280 T3316 C166 P31879 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index.20130227190956752 forceNew:false
[junit4:junit4] 2> 18280 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3
[junit4:junit4] 2> 18280 T3316 C166 P31879 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ab0882f lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bf25e10) fullCopy=true
[junit4:junit4] 2> 18283 T3276 C167 P15194 REQ /replication {file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 18284 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index
[junit4:junit4] 2> 18284 T3316 C166 P31879 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 18285 T3316 C166 P31879 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130227190956752
[junit4:junit4] 2> 18285 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3
[junit4:junit4] 2> 18286 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3
[junit4:junit4] 2> 18286 T3316 C166 P31879 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index/ new=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index.20130227190956752
[junit4:junit4] 2> 18288 T3316 C166 P31879 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ab0882f lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bf25e10),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18288 T3316 C166 P31879 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18289 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3
[junit4:junit4] 2> 18289 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3
[junit4:junit4] 2> 18290 T3316 C166 P31879 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 18290 T3316 C166 P31879 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 18290 T3316 C166 P31879 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 18291 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index.20130227190956752
[junit4:junit4] 2> 18291 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3
[junit4:junit4] 2> 18292 T3316 C166 P31879 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ab0882f lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bf25e10),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 18293 T3316 C166 P31879 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 18293 T3316 C166 P31879 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 18293 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3
[junit4:junit4] 2> 18294 T3316 C166 P31879 oass.SolrIndexSearcher.<init> Opening Searcher@36e51b5e main
[junit4:junit4] 2> 18295 T3315 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@36e51b5e main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 18295 T3315 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index
[junit4:junit4] 2> 18296 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index.20130227190956752
[junit4:junit4] 2> 18296 T3316 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index
[junit4:junit4] 2> 18296 T3316 C166 P31879 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 18296 T3316 C166 P31879 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 18297 T3316 C166 P31879 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 18297 T3316 C166 P31879 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18310 T3316 C166 P31879 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 18514 T3332 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 18514 T3332 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:23778/pz_dvy/e collection:collection1 shard:shard1
[junit4:junit4] 2> 18517 T3332 oasc.ZkController.register We are http://127.0.0.1:23778/pz_dvy/e/collection1/ and leader is http://127.0.0.1:15194/pz_dvy/e/collection1/
[junit4:junit4] 2> 18517 T3332 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:23778/pz_dvy/e
[junit4:junit4] 2> 18517 T3332 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 18517 T3332 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C168 name=collection1 org.apache.solr.core.SolrCore@7c658e28 url=http://127.0.0.1:23778/pz_dvy/e/collection1 node=127.0.0.1:23778_pz_dvy%2Fe C168_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:23778_pz_dvy%2Fe, base_url=http://127.0.0.1:23778/pz_dvy/e}
[junit4:junit4] 2> 18518 T3336 C168 P23778 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 18518 T3332 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18519 T3336 C168 P23778 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 18519 T3336 C168 P23778 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 18519 T3336 C168 P23778 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 18520 T3241 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 18520 T3241 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 18521 T3336 C168 P23778 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18521 T3241 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 18542 T3241 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18543 T3241 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 18544 T3241 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 18544 T3241 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19069 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19070 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[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:31879_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31879/pz_dvy/e"}
[junit4:junit4] 2> 19074 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:23778_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:23778/pz_dvy/e"}
[junit4:junit4] 2> 19091 T3282 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> 19091 T3297 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> 19091 T3263 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> 19091 T3329 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> 19091 T3313 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> 19091 T3269 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> 19546 T3241 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20548 T3241 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C168_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:23778_pz_dvy%2Fe, base_url=http://127.0.0.1:23778/pz_dvy/e}
[junit4:junit4] 2> 21544 T3336 C168 P23778 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:15194/pz_dvy/e/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 21544 T3336 C168 P23778 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:23778/pz_dvy/e START replicas=[http://127.0.0.1:15194/pz_dvy/e/collection1/] nUpdates=100
[junit4:junit4] 2> 21545 T3336 C168 P23778 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 21545 T3336 C168 P23778 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 21545 T3336 C168 P23778 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 21545 T3336 C168 P23778 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 21545 T3336 C168 P23778 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 21546 T3336 C168 P23778 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:15194/pz_dvy/e/collection1/. core=collection1
[junit4:junit4] 2> 21546 T3336 C168 P23778 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 21547 T3274 C167 P15194 REQ /get {getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 21550 T3241 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21557 T3272 C167 P15194 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 21558 T3272 C167 P15194 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=3
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21558 T3272 C167 P15194 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21559 T3272 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1
[junit4:junit4] 2> 21559 T3272 C167 P15194 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 21560 T3272 C167 P15194 /update {waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> 21561 T3336 C168 P23778 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 21561 T3336 C168 P23778 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 21563 T3276 C167 P15194 REQ /replication {command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 21564 T3336 C168 P23778 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 21564 T3336 C168 P23778 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 21564 T3336 C168 P23778 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 21566 T3276 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1
[junit4:junit4] 2> 21567 T3276 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/index
[junit4:junit4] 2> 21567 T3276 C167 P15194 REQ /replication {command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 21568 T3336 C168 P23778 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 21570 T3336 C168 P23778 oasc.CachingDirectoryFactory.get return new directory for /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index.20130227191000041 forceNew:false
[junit4:junit4] 2> 21570 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 21570 T3336 C168 P23778 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e3918db lockFactory=org.apache.lucene.store.NativeFSLockFactory@38f3a17d) fullCopy=true
[junit4:junit4] 2> 21573 T3276 C167 P15194 REQ /replication {file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 21574 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index
[junit4:junit4] 2> 21575 T3336 C168 P23778 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 21575 T3336 C168 P23778 oash.SnapPuller.modifyIndexProps New index installed. Updating index properties... index=index.20130227191000041
[junit4:junit4] 2> 21575 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 21576 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 21576 T3336 C168 P23778 oasc.SolrCore.getNewIndexDir New index directory detected: old=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index/ new=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index.20130227191000041
[junit4:junit4] 2> 21578 T3336 C168 P23778 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e3918db lockFactory=org.apache.lucene.store.NativeFSLockFactory@38f3a17d),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21579 T3336 C168 P23778 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21579 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 21579 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 21580 T3336 C168 P23778 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 21580 T3336 C168 P23778 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 21580 T3336 C168 P23778 oasu.DefaultSolrCoreState.newIndexWriter Rollback old IndexWriter... core=collection1
[junit4:junit4] 2> 21581 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index.20130227191000041
[junit4:junit4] 2> 21581 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 21583 T3336 C168 P23778 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e3918db lockFactory=org.apache.lucene.store.NativeFSLockFactory@38f3a17d),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 21583 T3336 C168 P23778 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 21583 T3336 C168 P23778 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 21584 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 21584 T3336 C168 P23778 oass.SolrIndexSearcher.<init> Opening Searcher@498779fb main
[junit4:junit4] 2> 21585 T3333 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@498779fb main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 21585 T3333 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index
[junit4:junit4] 2> 21586 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index.20130227191000041
[junit4:junit4] 2> 21586 T3336 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index
[junit4:junit4] 2> 21586 T3336 C168 P23778 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 21587 T3336 C168 P23778 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 21587 T3336 C168 P23778 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 21587 T3336 C168 P23778 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 21588 T3336 C168 P23778 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 22105 T3264 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22106 T3264 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[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:23778_pz_dvy%2Fe",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:23778/pz_dvy/e"}
[junit4:junit4] 2> 22124 T3269 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> 22124 T3297 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> 22124 T3329 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> 22124 T3263 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> 22124 T3313 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> 22124 T3282 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> 22552 T3241 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22553 T3241 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C169 name=collection1 org.apache.solr.core.SolrCore@112b4bf6 url=http://127.0.0.1:15185/pz_dvy/e/collection1 node=127.0.0.1:15185_pz_dvy%2Fe C169_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:15185_pz_dvy%2Fe, base_url=http://127.0.0.1:15185/pz_dvy/e, leader=true}
[junit4:junit4] 2> 22564 T3253 C169 P15185 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22566 T3253 C169 P15185 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data
[junit4:junit4] 2> 22568 T3253 C169 P15185 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@16851877 lockFactory=org.apache.lucene.store.NativeFSLockFactory@414751f9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 22569 T3253 C169 P15185 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 22569 T3253 C169 P15185 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@16851877 lockFactory=org.apache.lucene.store.NativeFSLockFactory@414751f9),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@16851877 lockFactory=org.apache.lucene.store.NativeFSLockFactory@414751f9),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 22570 T3253 C169 P15185 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 22570 T3253 C169 P15185 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data
[junit4:junit4] 2> 22571 T3253 C169 P15185 oass.SolrIndexSearcher.<init> Opening Searcher@5926721c main
[junit4:junit4] 2> 22571 T3253 C169 P15185 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22572 T3267 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5926721c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 22573 T3267 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/control/data/index
[junit4:junit4] 2> 22573 T3253 C169 P15185 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 22586 T3275 C167 P15194 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22587 T3275 C167 P15194 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=4
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@5a7b7658 lockFactory=org.apache.lucene.store.NativeFSLockFactory@208137b7),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 22587 T3275 C167 P15194 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 22588 T3275 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1
[junit4:junit4] 2> 22588 T3275 C167 P15194 oass.SolrIndexSearcher.<init> Opening Searcher@1c578d23 main
[junit4:junit4] 2> 22589 T3275 C167 P15194 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/index
[junit4:junit4] 2> 22589 T3275 C167 P15194 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22590 T3284 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c578d23 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 22591 T3284 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty1/index
[junit4:junit4] 2> 22591 T3275 C167 P15194 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:22940/pz_dvy/e/collection1/, StdNode: http://127.0.0.1:31879/pz_dvy/e/collection1/, StdNode: http://127.0.0.1:23778/pz_dvy/e/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> C168_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:23778_pz_dvy%2Fe, base_url=http://127.0.0.1:23778/pz_dvy/e}
[junit4:junit4] 2> 22601 T3319 C168 P23778 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C165_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:22940_pz_dvy%2Fe, base_url=http://127.0.0.1:22940/pz_dvy/e}
[junit4:junit4] 2> 22601 T3287 C165 P22940 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C166_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:31879_pz_dvy%2Fe, base_url=http://127.0.0.1:31879/pz_dvy/e}
[junit4:junit4] 2> 22601 T3303 C166 P31879 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22603 T3319 C168 P23778 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e3918db lockFactory=org.apache.lucene.store.NativeFSLockFactory@38f3a17d),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6e3918db lockFactory=org.apache.lucene.store.NativeFSLockFactory@38f3a17d),segFN=segments_5,generation=5,filenames=[segments_5]
[junit4:junit4] 2> 22603 T3287 C165 P22940 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@702ee8e lockFactory=org.apache.lucene.store.NativeFSLockFactory@f6ed9a1),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@702ee8e lockFactory=org.apache.lucene.store.NativeFSLockFactory@f6ed9a1),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> 22603 T3303 C166 P31879 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ab0882f lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bf25e10),segFN=segments_3,generation=3,filenames=[segments_3]
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ab0882f lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bf25e10),segFN=segments_4,generation=4,filenames=[segments_4]
[junit4:junit4] 2> 22604 T3319 C168 P23778 oasc.SolrDeletionPolicy.updateCommits newest commit = 5[segments_5]
[junit4:junit4] 2> 22604 T3287 C165 P22940 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[segments_3]
[junit4:junit4] 2> 22605 T3303 C166 P31879 oasc.SolrDeletionPolicy.updateCommits newest commit = 4[segments_4]
[junit4:junit4] 2> 22605 T3319 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 22606 T3303 C166 P31879 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3
[junit4:junit4] 2> 22606 T3287 C165 P22940 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2
[junit4:junit4] 2> 22606 T3319 C168 P23778 oass.SolrIndexSearcher.<init> Opening Searcher@c49111b main
[junit4:junit4] 2> 22606 T3303 C166 P31879 oass.SolrIndexSearcher.<init> Opening Searcher@1cd8ea5f main
[junit4:junit4] 2> 22607 T3319 C168 P23778 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22607 T3303 C166 P31879 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22607 T3315 oasc.JmxMonitoredMap.put WARNING Failed to register info bean: searcher javax.management.InstanceNotFoundException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getMBean(DefaultMBeanServerInterceptor.java:1095)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.exclusiveUnregisterMBean(DefaultMBeanServerInterceptor.java:427)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterMBean(DefaultMBeanServerInterceptor.java:415)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.unregisterMBean(JmxMBeanServer.java:536)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:138)
[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:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 22607 T3287 C165 P22940 oass.SolrIndexSearcher.<init> Opening Searcher@2c838eab main
[junit4:junit4] 2> 22608 T3333 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c49111b main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 22608 T3287 C165 P22940 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22609 T3315 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1cd8ea5f main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 22609 T3299 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2c838eab main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 22609 T3333 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index.20130227191000041
[junit4:junit4] 2> 22609 T3315 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty3/index.20130227190956752
[junit4:junit4] 2> 22609 T3319 C168 P23778 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 22610 T3303 C166 P31879 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 22610 T3299 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty2/index.20130227190954351
[junit4:junit4] 2> 22610 T3287 C165 P22940 /update {waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 22611 T3275 C167 P15194 /update {waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 25
[junit4:junit4] 2> 22612 T3241 oascc.ZkState
[...truncated too long message...]
sync replicas back to leader
[junit4:junit4] 2> 167403 T3329 oasc.ShardLeaderElectionContext.rejoinLeaderElection Not rejoining election because CoreContainer is shutdown
[junit4:junit4] 2> 167403 T3329 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@7c658e28
[junit4:junit4] 2> 167404 T3329 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> 167404 T3329 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 167405 T3329 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 167405 T3329 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 167405 T3329 C168 P23778 oasu.TransactionLog.forceClose SEVERE Error: Forcing close of tlog{file=./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/tlog/tlog.0000000000000000005 refcount=1}
[junit4:junit4] 2> 167408 T3329 C168 P23778 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index.20130227191000041
[junit4:junit4] 2> 167408 T3329 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 167460 T3329 oasc.CachingDirectoryFactory.close Releasing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index.20130227191000041
[junit4:junit4] 2> 167460 T3329 oasc.CachingDirectoryFactory.close Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index.20130227191000041
[junit4:junit4] 2> 167461 T3329 oash.SnapPuller$2.preClose removing old index files BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@7a91ffba lockFactory=org.apache.lucene.store.NativeFSLockFactory@6cfd4699)
[junit4:junit4] 2> 167461 T3329 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index.20130227191000041
[junit4:junit4] 2> 167461 T3329 oash.SnapPuller$2.postClose removing old index directory BaseDirectoryWrapper(org.apache.lucene.store.RAMDirectory@7a91ffba lockFactory=org.apache.lucene.store.NativeFSLockFactory@6cfd4699)
[junit4:junit4] 2> 167461 T3329 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index
[junit4:junit4] 2> 167462 T3329 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4/index
[junit4:junit4] 2> 167462 T3329 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 167462 T3329 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-1362013778479/jetty4
[junit4:junit4] 2> 167463 T3329 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 167463 T3329 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> 167463 T3329 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 167463 T3329 oasc.LeaderElector$1.process WARNING org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:236)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:233)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:233)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 167464 T3329 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> NOTE: test params are: codec=SimpleText, sim=DefaultSimilarity, locale=no_NO, timezone=America/Costa_Rica
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Oracle Corporation 1.7.0_09 (64-bit)/cpus=16,threads=3,free=237647720,total=457179136
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestGroupingSearch, TestFuzzyAnalyzedSuggestions, TestLFUCache, SpellCheckComponentTest, OverseerCollectionProcessorTest, PreAnalyzedFieldTest, NumericFieldsTest, AutoCommitTest, SystemInfoHandlerTest, DateFieldTest, TestQueryTypes, TestStressLucene, TestNumberUtils, LeaderElectionIntegrationTest, TestCoreContainer, SolrCoreCheckLockOnStartupTest, SampleTest, TestRandomDVFaceting, UpdateRequestProcessorFactoryTest, SortByFunctionTest, AlternateDirectoryTest, ResourceLoaderTest, JSONWriterTest, ZkCLITest, SearchHandlerTest, TestIndexingPerformance, TestFastLRUCache, TestXIncludeConfig, ScriptEngineTest, TestReload, CurrencyFieldTest, TestFastWriter, PathHierarchyTokenizerFactoryTest, TestSolrQueryParser, JsonLoaderTest, TestLMDirichletSimilarityFactory, TestRangeQuery, TestIBSimilarityFactory, DirectSolrConnectionTest, SimplePostToolTest, MinimalSchemaTest, TestExtendedDismaxParser, MBeansHandlerTest, DistanceFunctionTest, TestStressRecovery, TestSuggestSpellingConverter, TestCollationField, BadComponentTest, TestLuceneMatchVersion, WordBreakSolrSpellCheckerTest, BasicDistributedZkTest, SuggesterFSTTest, IndexBasedSpellCheckerTest, TestRandomFaceting, TestIndexSearcher, FileBasedSpellCheckerTest, TestStressReorder, LoggingHandlerTest, MoreLikeThisHandlerTest, HighlighterConfigTest, OverseerTest, LeaderElectionTest, DistributedSpellCheckComponentTest, TestRealTimeGet, ZkControllerTest, TestDistributedGrouping, SpellCheckCollatorTest, SoftAutoCommitTest, ZkSolrClientTest, TestFaceting, DistributedTermsComponentTest, TestJoin, TestFunctionQuery, SolrRequestParserTest, QueryEqualityTest, TestWordDelimiterFilterFactory, SpatialFilterTest, TestPseudoReturnFields, BinaryUpdateRequestHandlerTest, SolrInfoMBeanTest, StandardRequestHandlerTest, FieldAnalysisRequestHandlerTest, DirectUpdateHandlerOptimizeTest, SolrPluginUtilsTest, FastVectorHighlighterTest, DebugComponentTest, RequiredFieldsTest, CopyFieldTest, SolrCmdDistributorTest, TestQuerySenderListener, TestQuerySenderNoQuery, TestSolrCoreProperties, TestJmxMonitoredMap, EchoParamsTest, TestBM25SimilarityFactory, TestLMJelinekMercerSimilarityFactory, TestCodecSupport, DateMathParserTest, OpenExchangeRatesOrgProviderTest, TestSolrXMLSerializer, TestBadConfig, UUIDFieldTest, RAMDirectoryFactoryTest, ChaosMonkeyNothingIsSafeTest, CircularListTest, TestDocumentBuilder, TestCharFilters, ClusterStateUpdateTest, ShardRoutingCustomTest, ShardRoutingTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 167.64s, 1 test, 1 failure <<< FAILURES!
[...truncated 68 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:381: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:361: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/build.xml:183: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/solr/common-build.xml:447: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:1202: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-java7/lucene/common-build.xml:865: There were test failures: 257 suites, 1075 tests, 1 failure, 22 ignored (4 assumptions)
Total time: 49 minutes 9 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure