You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/03/02 00:25:27 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/ibm-j9-jdk7) - Build #
4538 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/4538/
Java: 32bit/ibm-j9-jdk7
1 tests failed.
REGRESSION: org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch
Error Message:
expected:<1> but was:<0>
Stack Trace:
java.lang.AssertionError: expected:<1> but was:<0>
at __randomizedtesting.SeedInfo.seed([49985899AC86F75F:C87ED681DBD99763]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.junit.Assert.assertEquals(Assert.java:456)
at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:209)
at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:613)
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:780)
Build Log:
[...truncated 9513 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4] 2> 0 T2566 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /dms/u
[junit4:junit4] 2> 3 T2566 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075
[junit4:junit4] 2> 4 T2566 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 5 T2567 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 6 T2567 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4] 2> 6 T2567 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4] 2> 6 T2567 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4] 2> 9 T2567 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> 9 T2567 oazsp.FileTxnSnapLog.save Snapshotting: 0x0 to /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4] 2> 105 T2566 oasc.ZkTestServer.run start zk server on port:51525
[junit4:junit4] 2> 106 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@691574f4
[junit4:junit4] 2> 109 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 109 T2572 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 110 T2572 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 110 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41319
[junit4:junit4] 2> 110 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41319
[junit4:junit4] 2> 111 T2570 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4] 2> 125 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d284410410000 with negotiated timeout 10000 for client /127.0.0.1:41319
[junit4:junit4] 2> 125 T2572 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d284410410000, negotiated timeout = 10000
[junit4:junit4] 2> 126 T2573 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@691574f4 name:ZooKeeperConnection Watcher:127.0.0.1:51525 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 126 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 127 T2566 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 130 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d284410410000
[junit4:junit4] 2> 130 T2573 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 130 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41319 which had sessionid 0x13d284410410000
[junit4:junit4] 2> 130 T2566 oaz.ZooKeeper.close Session: 0x13d284410410000 closed
[junit4:junit4] 2> 131 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@8cd604fa
[junit4:junit4] 2> 133 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 134 T2574 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 134 T2574 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 134 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41320
[junit4:junit4] 2> 135 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41320
[junit4:junit4] 2> 136 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d284410410001 with negotiated timeout 10000 for client /127.0.0.1:41320
[junit4:junit4] 2> 136 T2574 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d284410410001, negotiated timeout = 10000
[junit4:junit4] 2> 136 T2575 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8cd604fa name:ZooKeeperConnection Watcher:127.0.0.1:51525/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 137 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 137 T2566 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 139 T2566 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 141 T2566 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 143 T2566 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 145 T2566 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 146 T2566 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 148 T2566 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 149 T2566 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 152 T2566 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 152 T2566 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 154 T2566 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 154 T2566 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 156 T2566 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 157 T2566 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 159 T2566 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 159 T2566 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 161 T2566 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 162 T2566 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 164 T2566 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 164 T2566 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 166 T2566 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 167 T2566 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 169 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d284410410001
[junit4:junit4] 2> 169 T2575 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 169 T2566 oaz.ZooKeeper.close Session: 0x13d284410410001 closed
[junit4:junit4] 2> 169 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41320 which had sessionid 0x13d284410410001
[junit4:junit4] 2> 223 T2566 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 228 T2566 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:57831
[junit4:junit4] 2> 229 T2566 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 230 T2566 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 230 T2566 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362180182241
[junit4:junit4] 2> 231 T2566 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362180182241/solr.xml
[junit4:junit4] 2> 231 T2566 oasc.CoreContainer.<init> New CoreContainer 870037408
[junit4:junit4] 2> 232 T2566 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362180182241/'
[junit4:junit4] 2> 233 T2566 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362180182241/'
[junit4:junit4] 2> 245 T2566 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 245 T2566 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 246 T2566 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 246 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 247 T2566 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 247 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 248 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 249 T2566 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 249 T2566 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 250 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 257 T2566 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 267 T2566 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:51525/solr
[junit4:junit4] 2> 268 T2566 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 268 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@86772f4e
[junit4:junit4] 2> 271 T2585 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 271 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 272 T2585 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 272 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41321
[junit4:junit4] 2> 272 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41321
[junit4:junit4] 2> 273 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d284410410002 with negotiated timeout 20000 for client /127.0.0.1:41321
[junit4:junit4] 2> 273 T2585 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d284410410002, negotiated timeout = 20000
[junit4:junit4] 2> 274 T2586 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@86772f4e name:ZooKeeperConnection Watcher:127.0.0.1:51525 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 274 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 275 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d284410410002
[junit4:junit4] 2> 275 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41321 which had sessionid 0x13d284410410002
[junit4:junit4] 2> 275 T2586 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 275 T2566 oaz.ZooKeeper.close Session: 0x13d284410410002 closed
[junit4:junit4] 2> 276 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 281 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@684c50b9
[junit4:junit4] 2> 284 T2587 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 284 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 285 T2587 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 285 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41322
[junit4:junit4] 2> 285 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41322
[junit4:junit4] 2> 286 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d284410410003 with negotiated timeout 20000 for client /127.0.0.1:41322
[junit4:junit4] 2> 286 T2587 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d284410410003, negotiated timeout = 20000
[junit4:junit4] 2> 287 T2588 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@684c50b9 name:ZooKeeperConnection Watcher:127.0.0.1:51525/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 287 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 288 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 type:create cxid:0x2 zxid:0x1a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 290 T2566 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 291 T2566 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57831_dms%2Fu
[junit4:junit4] 2> 292 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 type:delete cxid:0x8 zxid:0x1c txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:57831_dms%2Fu Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:57831_dms%2Fu
[junit4:junit4] 2> 293 T2566 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57831_dms%2Fu
[junit4:junit4] 2> 295 T2566 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 298 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 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> 299 T2566 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 300 T2566 oasc.Overseer.start Overseer (id=89271840412860419-127.0.0.1:57831_dms%2Fu-n_0000000000) starting
[junit4:junit4] 2> 301 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 type:create cxid:0x1b zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 302 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 type:create cxid:0x1c zxid:0x24 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 302 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 type:create cxid:0x1d zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 303 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 type:create cxid:0x1e zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 305 T2590 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 306 T2566 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 308 T2566 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 310 T2589 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 312 T2591 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362180182241/collection1
[junit4:junit4] 2> 312 T2591 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 313 T2591 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 313 T2591 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 314 T2591 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362180182241/collection1/'
[junit4:junit4] 2> 315 T2591 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362180182241/collection1/lib/README' to classloader
[junit4:junit4] 2> 315 T2591 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362180182241/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 346 T2591 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 374 T2591 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 375 T2591 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 379 T2591 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 678 T2591 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 683 T2591 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 685 T2591 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 694 T2591 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 698 T2591 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 702 T2591 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 703 T2591 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 703 T2591 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 703 T2591 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 704 T2591 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 705 T2591 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 705 T2591 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1362180182241/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data/
[junit4:junit4] 2> 705 T2591 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@8f7e7357
[junit4:junit4] 2> 706 T2591 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 707 T2591 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data forceNew:false
[junit4:junit4] 2> 707 T2591 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data
[junit4:junit4] 2> 708 T2591 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data/index/
[junit4:junit4] 2> 708 T2591 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 709 T2591 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data/index forceNew:false
[junit4:junit4] 2> 710 T2591 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@d26a1f6b lockFactory=org.apache.lucene.store.NativeFSLockFactory@acbe0c10; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 710 T2591 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 711 T2591 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data/index
[junit4:junit4] 2> 712 T2591 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 713 T2591 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 713 T2591 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 714 T2591 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 714 T2591 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 714 T2591 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 715 T2591 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 715 T2591 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 715 T2591 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 717 T2591 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 718 T2591 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data
[junit4:junit4] 2> 719 T2591 oass.SolrIndexSearcher.<init> Opening Searcher@1b36ee1c main
[junit4:junit4] 2> 719 T2591 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data/tlog
[junit4:junit4] 2> 720 T2591 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 720 T2591 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 723 T2591 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data
[junit4:junit4] 2> 723 T2592 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b36ee1c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 724 T2591 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 724 T2591 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 725 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 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> 1812 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1813 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57831/dms/u",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57831_dms%2Fu",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 1814 T2589 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1814 T2589 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 1814 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 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> 1818 T2588 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> 2727 T2591 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2728 T2591 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57831/dms/u collection:control_collection shard:shard1
[junit4:junit4] 2> 2729 T2591 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2733 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 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> 2734 T2591 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2734 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 type:create cxid:0x73 zxid:0x37 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 2735 T2591 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2736 T2591 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2736 T2591 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57831/dms/u/collection1/
[junit4:junit4] 2> 2736 T2591 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2737 T2591 oasc.SyncStrategy.syncToMe http://127.0.0.1:57831/dms/u/collection1/ has no replicas
[junit4:junit4] 2> 2737 T2591 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57831/dms/u/collection1/
[junit4:junit4] 2> 2737 T2591 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2740 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410003 type:create cxid:0x7d zxid:0x3b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3320 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3326 T2588 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> 3344 T2591 oasc.ZkController.register We are http://127.0.0.1:57831/dms/u/collection1/ and leader is http://127.0.0.1:57831/dms/u/collection1/
[junit4:junit4] 2> 3344 T2591 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57831/dms/u
[junit4:junit4] 2> 3344 T2591 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3345 T2591 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3345 T2591 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3346 T2591 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3347 T2566 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 3348 T2566 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3348 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3353 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3354 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@36a4bb0
[junit4:junit4] 2> 3356 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3357 T2593 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3357 T2593 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 3357 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41325
[junit4:junit4] 2> 3358 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41325
[junit4:junit4] 2> 3359 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d284410410004 with negotiated timeout 10000 for client /127.0.0.1:41325
[junit4:junit4] 2> 3359 T2593 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d284410410004, negotiated timeout = 10000
[junit4:junit4] 2> 3359 T2594 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@36a4bb0 name:ZooKeeperConnection Watcher:127.0.0.1:51525/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3360 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3360 T2566 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3362 T2566 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3415 T2566 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 3420 T2566 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58579
[junit4:junit4] 2> 3420 T2566 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3421 T2566 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3422 T2566 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433
[junit4:junit4] 2> 3422 T2566 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/solr.xml
[junit4:junit4] 2> 3423 T2566 oasc.CoreContainer.<init> New CoreContainer -44108160
[junit4:junit4] 2> 3423 T2566 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/'
[junit4:junit4] 2> 3424 T2566 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/'
[junit4:junit4] 2> 3436 T2566 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3436 T2566 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3437 T2566 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3437 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3438 T2566 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3439 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3439 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3440 T2566 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3440 T2566 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3441 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3448 T2566 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 3458 T2566 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:51525/solr
[junit4:junit4] 2> 3458 T2566 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3459 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@77a3654b
[junit4:junit4] 2> 3462 T2604 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3462 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3462 T2604 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 3463 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41326
[junit4:junit4] 2> 3463 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41326
[junit4:junit4] 2> 3464 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d284410410005 with negotiated timeout 20000 for client /127.0.0.1:41326
[junit4:junit4] 2> 3464 T2604 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d284410410005, negotiated timeout = 20000
[junit4:junit4] 2> 3464 T2605 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@77a3654b name:ZooKeeperConnection Watcher:127.0.0.1:51525 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3465 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3466 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d284410410005
[junit4:junit4] 2> 3467 T2605 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 3467 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41326 which had sessionid 0x13d284410410005
[junit4:junit4] 2> 3467 T2566 oaz.ZooKeeper.close Session: 0x13d284410410005 closed
[junit4:junit4] 2> 3468 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3473 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@d9aa9b0b
[junit4:junit4] 2> 3475 T2606 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 3475 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3476 T2606 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 3476 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41327
[junit4:junit4] 2> 3476 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41327
[junit4:junit4] 2> 3477 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d284410410006 with negotiated timeout 20000 for client /127.0.0.1:41327
[junit4:junit4] 2> 3477 T2606 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d284410410006, negotiated timeout = 20000
[junit4:junit4] 2> 3477 T2607 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d9aa9b0b name:ZooKeeperConnection Watcher:127.0.0.1:51525/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3478 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3478 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:create cxid:0x1 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3479 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:create cxid:0x2 zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 3480 T2566 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 4482 T2566 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58579_dms%2Fu
[junit4:junit4] 2> 4483 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:delete cxid:0x9 zxid:0x4b txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:58579_dms%2Fu Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:58579_dms%2Fu
[junit4:junit4] 2> 4484 T2566 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58579_dms%2Fu
[junit4:junit4] 2> 4486 T2594 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4486 T2607 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4487 T2588 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 4487 T2588 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> 4491 T2608 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/collection1
[junit4:junit4] 2> 4491 T2608 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 4492 T2608 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 4492 T2608 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 4494 T2608 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/collection1/'
[junit4:junit4] 2> 4494 T2608 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/collection1/lib/README' to classloader
[junit4:junit4] 2> 4495 T2608 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 4518 T2608 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 4546 T2608 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 4547 T2608 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 4551 T2608 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 4830 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 4831 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57831/dms/u",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:57831_dms%2Fu",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 4834 T2607 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> 4834 T2588 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> 4834 T2594 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> 4852 T2608 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 4857 T2608 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 4860 T2608 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 4869 T2608 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 4872 T2608 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 4876 T2608 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 4877 T2608 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 4877 T2608 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 4878 T2608 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 4879 T2608 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 4879 T2608 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 4879 T2608 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/
[junit4:junit4] 2> 4880 T2608 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@8f7e7357
[junit4:junit4] 2> 4880 T2608 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 4882 T2608 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1 forceNew:false
[junit4:junit4] 2> 4882 T2608 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1
[junit4:junit4] 2> 4882 T2608 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index/
[junit4:junit4] 2> 4883 T2608 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 4883 T2608 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index forceNew:false
[junit4:junit4] 2> 4884 T2608 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5ef186c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a6d29fcd; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 4885 T2608 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 4886 T2608 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index
[junit4:junit4] 2> 4887 T2608 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 4887 T2608 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 4888 T2608 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 4888 T2608 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 4889 T2608 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 4889 T2608 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 4890 T2608 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 4890 T2608 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 4891 T2608 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 4892 T2608 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 4894 T2608 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1
[junit4:junit4] 2> 4894 T2608 oass.SolrIndexSearcher.<init> Opening Searcher@c94aeb48 main
[junit4:junit4] 2> 4894 T2608 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/tlog
[junit4:junit4] 2> 4895 T2608 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 4895 T2608 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 4899 T2609 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c94aeb48 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 4901 T2608 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 4901 T2608 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 6338 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 6339 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58579/dms/u",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58579_dms%2Fu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 6339 T2589 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 6339 T2589 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 6342 T2607 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> 6342 T2594 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> 6342 T2588 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> 6902 T2608 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 6903 T2608 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58579/dms/u collection:collection1 shard:shard1
[junit4:junit4] 2> 6904 T2608 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 6910 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:delete cxid:0x46 zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4] 2> 6910 T2608 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 6911 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:create cxid:0x47 zxid:0x5c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 6912 T2608 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 6913 T2608 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 6913 T2608 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58579/dms/u/collection1/
[junit4:junit4] 2> 6913 T2608 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 6914 T2608 oasc.SyncStrategy.syncToMe http://127.0.0.1:58579/dms/u/collection1/ has no replicas
[junit4:junit4] 2> 6914 T2608 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58579/dms/u/collection1/
[junit4:junit4] 2> 6914 T2608 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 6917 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:create cxid:0x51 zxid:0x60 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 7847 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 7853 T2607 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> 7853 T2594 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> 7853 T2588 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> 7871 T2608 oasc.ZkController.register We are http://127.0.0.1:58579/dms/u/collection1/ and leader is http://127.0.0.1:58579/dms/u/collection1/
[junit4:junit4] 2> 7871 T2608 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58579/dms/u
[junit4:junit4] 2> 7872 T2608 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 7872 T2608 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 7872 T2608 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 7874 T2608 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 7875 T2566 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 7876 T2566 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 7876 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 7933 T2566 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 7940 T2566 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37469
[junit4:junit4] 2> 7940 T2566 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 7941 T2566 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 7942 T2566 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362180189952
[junit4:junit4] 2> 7942 T2566 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362180189952/solr.xml
[junit4:junit4] 2> 7943 T2566 oasc.CoreContainer.<init> New CoreContainer -350454147
[junit4:junit4] 2> 7943 T2566 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362180189952/'
[junit4:junit4] 2> 7944 T2566 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362180189952/'
[junit4:junit4] 2> 7956 T2566 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 7957 T2566 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 7957 T2566 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 7958 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 7958 T2566 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 7959 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 7959 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 7960 T2566 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 7961 T2566 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 7961 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 7969 T2566 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 7979 T2566 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:51525/solr
[junit4:junit4] 2> 7979 T2566 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 7980 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@b558072
[junit4:junit4] 2> 7983 T2619 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 7983 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 7984 T2619 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 7984 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41330
[junit4:junit4] 2> 7985 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41330
[junit4:junit4] 2> 7986 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d284410410007 with negotiated timeout 20000 for client /127.0.0.1:41330
[junit4:junit4] 2> 7986 T2619 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d284410410007, negotiated timeout = 20000
[junit4:junit4] 2> 7986 T2620 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b558072 name:ZooKeeperConnection Watcher:127.0.0.1:51525 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 7986 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 7987 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d284410410007
[junit4:junit4] 2> 7988 T2620 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 7988 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41330 which had sessionid 0x13d284410410007
[junit4:junit4] 2> 7988 T2566 oaz.ZooKeeper.close Session: 0x13d284410410007 closed
[junit4:junit4] 2> 7989 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 7994 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@d70404ca
[junit4:junit4] 2> 7996 T2621 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 7996 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 7997 T2621 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 7997 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41331
[junit4:junit4] 2> 7997 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41331
[junit4:junit4] 2> 7998 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d284410410008 with negotiated timeout 20000 for client /127.0.0.1:41331
[junit4:junit4] 2> 7998 T2621 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d284410410008, negotiated timeout = 20000
[junit4:junit4] 2> 7999 T2622 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d70404ca name:ZooKeeperConnection Watcher:127.0.0.1:51525/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 7999 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 8000 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:create cxid:0x1 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8000 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:create cxid:0x2 zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 8002 T2566 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 9004 T2566 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37469_dms%2Fu
[junit4:junit4] 2> 9005 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:delete cxid:0x9 zxid:0x6f txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:37469_dms%2Fu Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:37469_dms%2Fu
[junit4:junit4] 2> 9005 T2566 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37469_dms%2Fu
[junit4:junit4] 2> 9008 T2607 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> 9008 T2622 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9008 T2594 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9008 T2588 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9009 T2594 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> 9009 T2588 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> 9010 T2607 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 9016 T2623 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362180189952/collection1
[junit4:junit4] 2> 9016 T2623 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 9017 T2623 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 9017 T2623 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 9018 T2623 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362180189952/collection1/'
[junit4:junit4] 2> 9019 T2623 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362180189952/collection1/lib/README' to classloader
[junit4:junit4] 2> 9019 T2623 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362180189952/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 9042 T2623 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 9071 T2623 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 9072 T2623 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 9076 T2623 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 9357 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 9357 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58579/dms/u",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58579_dms%2Fu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 9360 T2607 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> 9360 T2622 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> 9360 T2594 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> 9360 T2588 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> 9380 T2623 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 9385 T2623 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 9387 T2623 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 9396 T2623 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9400 T2623 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 9404 T2623 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9406 T2623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9406 T2623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9406 T2623 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 9407 T2623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 9408 T2623 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 9408 T2623 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1362180189952/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/
[junit4:junit4] 2> 9409 T2623 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@8f7e7357
[junit4:junit4] 2> 9409 T2623 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 9410 T2623 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2 forceNew:false
[junit4:junit4] 2> 9411 T2623 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2
[junit4:junit4] 2> 9411 T2623 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/index/
[junit4:junit4] 2> 9412 T2623 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 9412 T2623 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/index forceNew:false
[junit4:junit4] 2> 9413 T2623 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@c84d9342 lockFactory=org.apache.lucene.store.NativeFSLockFactory@b3e98722; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 9414 T2623 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 9415 T2623 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/index
[junit4:junit4] 2> 9416 T2623 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 9416 T2623 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 9417 T2623 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 9418 T2623 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 9418 T2623 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 9418 T2623 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 9419 T2623 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 9419 T2623 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 9420 T2623 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 9421 T2623 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 9423 T2623 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2
[junit4:junit4] 2> 9423 T2623 oass.SolrIndexSearcher.<init> Opening Searcher@c57dae42 main
[junit4:junit4] 2> 9424 T2623 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/tlog
[junit4:junit4] 2> 9425 T2623 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 9425 T2623 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 9430 T2624 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c57dae42 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 9432 T2623 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 9432 T2623 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 10864 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 10865 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37469/dms/u",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:37469_dms%2Fu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 10865 T2589 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 10866 T2589 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4] 2> 10869 T2594 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> 10870 T2622 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> 10869 T2607 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> 10870 T2588 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> 11434 T2623 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 11434 T2623 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37469/dms/u collection:collection1 shard:shard2
[junit4:junit4] 2> 11435 T2623 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 11440 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:delete cxid:0x45 zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard2 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard2
[junit4:junit4] 2> 11440 T2623 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 11441 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:create cxid:0x46 zxid:0x7f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 11442 T2623 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 11442 T2623 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 11442 T2623 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:37469/dms/u/collection1/
[junit4:junit4] 2> 11443 T2623 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 11443 T2623 oasc.SyncStrategy.syncToMe http://127.0.0.1:37469/dms/u/collection1/ has no replicas
[junit4:junit4] 2> 11443 T2623 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:37469/dms/u/collection1/
[junit4:junit4] 2> 11444 T2623 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 11446 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:create cxid:0x4f zxid:0x82 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12373 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12381 T2588 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> 12381 T2594 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> 12381 T2607 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> 12381 T2622 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> 12400 T2623 oasc.ZkController.register We are http://127.0.0.1:37469/dms/u/collection1/ and leader is http://127.0.0.1:37469/dms/u/collection1/
[junit4:junit4] 2> 12400 T2623 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37469/dms/u
[junit4:junit4] 2> 12400 T2623 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 12401 T2623 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 12401 T2623 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 12403 T2623 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 12404 T2566 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 12405 T2566 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 12406 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 12484 T2566 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4] 2> 12489 T2566 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:45522
[junit4:junit4] 2> 12489 T2566 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 12490 T2566 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 12491 T2566 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362180194485
[junit4:junit4] 2> 12491 T2566 oasc.CoreContainer$Initializer.initialize looking for solr.xml: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362180194485/solr.xml
[junit4:junit4] 2> 12492 T2566 oasc.CoreContainer.<init> New CoreContainer 612351451
[junit4:junit4] 2> 12493 T2566 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362180194485/'
[junit4:junit4] 2> 12493 T2566 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362180194485/'
[junit4:junit4] 2> 12506 T2566 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 12506 T2566 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 12507 T2566 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 12508 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 12508 T2566 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 12509 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 12509 T2566 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 12510 T2566 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 12511 T2566 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 12511 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 12519 T2566 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4] 2> 12529 T2566 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:51525/solr
[junit4:junit4] 2> 12530 T2566 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 12531 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@ce296800
[junit4:junit4] 2> 12534 T2634 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 12533 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 12534 T2634 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 12534 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41335
[junit4:junit4] 2> 12535 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41335
[junit4:junit4] 2> 12536 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d284410410009 with negotiated timeout 20000 for client /127.0.0.1:41335
[junit4:junit4] 2> 12536 T2634 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d284410410009, negotiated timeout = 20000
[junit4:junit4] 2> 12536 T2635 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ce296800 name:ZooKeeperConnection Watcher:127.0.0.1:51525 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 12536 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 12537 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d284410410009
[junit4:junit4] 2> 12538 T2635 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 12538 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41335 which had sessionid 0x13d284410410009
[junit4:junit4] 2> 12538 T2566 oaz.ZooKeeper.close Session: 0x13d284410410009 closed
[junit4:junit4] 2> 12539 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 12544 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@7d92de9a
[junit4:junit4] 2> 12548 T2636 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 12547 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 12548 T2636 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 12548 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41336
[junit4:junit4] 2> 12549 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41336
[junit4:junit4] 2> 12550 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d28441041000a with negotiated timeout 20000 for client /127.0.0.1:41336
[junit4:junit4] 2> 12550 T2636 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d28441041000a, negotiated timeout = 20000
[junit4:junit4] 2> 12550 T2637 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7d92de9a name:ZooKeeperConnection Watcher:127.0.0.1:51525/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 12551 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 12552 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:create cxid:0x1 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12553 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:create cxid:0x2 zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 12554 T2566 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 13556 T2566 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45522_dms%2Fu
[junit4:junit4] 2> 13557 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:delete cxid:0x9 zxid:0x91 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:45522_dms%2Fu Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:45522_dms%2Fu
[junit4:junit4] 2> 13558 T2566 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45522_dms%2Fu
[junit4:junit4] 2> 13560 T2607 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> 13560 T2622 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> 13560 T2588 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13560 T2594 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13560 T2637 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13560 T2588 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> 13561 T2594 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> 13561 T2607 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13562 T2622 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 13565 T2638 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362180194485/collection1
[junit4:junit4] 2> 13566 T2638 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 13566 T2638 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 13567 T2638 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 13568 T2638 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362180194485/collection1/'
[junit4:junit4] 2> 13568 T2638 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362180194485/collection1/lib/README' to classloader
[junit4:junit4] 2> 13569 T2638 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362180194485/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 13591 T2638 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 13619 T2638 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 13620 T2638 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 13624 T2638 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 13886 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 13886 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37469/dms/u",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:37469_dms%2Fu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 13890 T2594 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> 13890 T2637 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> 13890 T2622 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> 13890 T2588 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> 13890 T2607 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> 13930 T2638 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 13935 T2638 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 13938 T2638 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 13947 T2638 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13950 T2638 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 13954 T2638 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13955 T2638 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 13955 T2638 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 13956 T2638 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 13956 T2638 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 13957 T2638 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 13957 T2638 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1362180194485/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/
[junit4:junit4] 2> 13958 T2638 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@8f7e7357
[junit4:junit4] 2> 13958 T2638 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 13959 T2638 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3 forceNew:false
[junit4:junit4] 2> 13960 T2638 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 13960 T2638 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index/
[junit4:junit4] 2> 13960 T2638 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 13961 T2638 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index forceNew:false
[junit4:junit4] 2> 13962 T2638 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7f1deb2d lockFactory=org.apache.lucene.store.NativeFSLockFactory@651abeb7; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 13962 T2638 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 13963 T2638 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index
[junit4:junit4] 2> 13964 T2638 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 13965 T2638 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 13965 T2638 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 13966 T2638 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 13966 T2638 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 13966 T2638 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 13967 T2638 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 13967 T2638 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 13968 T2638 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 13969 T2638 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 13971 T2638 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 13971 T2638 oass.SolrIndexSearcher.<init> Opening Searcher@c9a47290 main
[junit4:junit4] 2> 13971 T2638 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/tlog
[junit4:junit4] 2> 13972 T2638 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 13972 T2638 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 13977 T2639 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c9a47290 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 13978 T2638 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 13978 T2638 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15394 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15394 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45522/dms/u",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:45522_dms%2Fu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 15395 T2589 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 15395 T2589 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 15398 T2637 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> 15398 T2622 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> 15398 T2607 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> 15400 T2594 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> 15400 T2588 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> 15980 T2638 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 15980 T2638 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45522/dms/u collection:collection1 shard:shard1
[junit4:junit4] 2> 15982 T2638 oasc.ZkController.register We are http://127.0.0.1:45522/dms/u/collection1/ and leader is http://127.0.0.1:58579/dms/u/collection1/
[junit4:junit4] 2> 15983 T2638 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45522/dms/u
[junit4:junit4] 2> 15983 T2638 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 15983 T2638 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C215 name=collection1 org.apache.solr.core.SolrCore@85c8d2cb url=http://127.0.0.1:45522/dms/u/collection1 node=127.0.0.1:45522_dms%2Fu C215_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:45522/dms/u, state=down, node_name=127.0.0.1:45522_dms%2Fu, collection=collection1, core=collection1}
[junit4:junit4] 2> 15984 T2640 C215 P45522 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 15984 T2640 C215 P45522 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 15984 T2638 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15984 T2640 C215 P45522 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 15985 T2640 C215 P45522 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 15985 T2566 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 15986 T2640 C215 P45522 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15986 T2566 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 15986 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 15991 T2566 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 15992 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 16701 T2602 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/onenodecollectioncore
[junit4:junit4] 2> 16702 T2602 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4] 2> 16703 T2602 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4] 2> 16703 T2602 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 16704 T2602 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 16705 T2602 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4] 2> 16707 T2602 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4] 2> 16708 T2602 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/onenodecollectioncore/'
[junit4:junit4] 2> 16732 T2602 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 16761 T2602 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 16762 T2602 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4] 2> 16766 T2602 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4] 2> 16901 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16902 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45522/dms/u",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:45522_dms%2Fu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 16905 T2588 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> 16905 T2637 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> 16905 T2594 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> 16905 T2607 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> 16906 T2622 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> 17091 T2602 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 17096 T2602 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 17098 T2602 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 17107 T2602 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 17111 T2602 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 17114 T2602 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 17115 T2602 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 17116 T2602 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 17116 T2602 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 17117 T2602 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 17118 T2602 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4] 2> 17119 T2602 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1362180185433/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection/
[junit4:junit4] 2> 17119 T2602 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@8f7e7357
[junit4:junit4] 2> 17120 T2602 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 17122 T2602 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection forceNew:false
[junit4:junit4] 2> 17122 T2602 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection
[junit4:junit4] 2> 17123 T2602 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection/index/
[junit4:junit4] 2> 17123 T2602 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 17124 T2602 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection/index forceNew:false
[junit4:junit4] 2> 17126 T2602 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@a533ef4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bd6bb77d; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 17126 T2602 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 17127 T2602 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection/index
[junit4:junit4] 2> 17129 T2602 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 17129 T2602 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 17130 T2602 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 17131 T2602 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 17131 T2602 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 17132 T2602 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 17132 T2602 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 17133 T2602 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 17134 T2602 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 17135 T2602 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 17137 T2602 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection
[junit4:junit4] 2> 17138 T2602 oass.SolrIndexSearcher.<init> Opening Searcher@f5ccafa6 main
[junit4:junit4] 2> 17138 T2602 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection/tlog
[junit4:junit4] 2> 17139 T2602 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 17140 T2602 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 17143 T2641 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@f5ccafa6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 17145 T2602 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 18409 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 18410 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58579/dms/u",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58579_dms%2Fu",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 18410 T2589 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4] 2> 18411 T2589 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 18425 T2594 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> 18425 T2637 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> 18425 T2607 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> 18425 T2588 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> 18425 T2622 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> 19146 T2602 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4] 2> 19147 T2602 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:58579/dms/u collection:onenodecollection shard:shard1
[junit4:junit4] 2> 19149 T2602 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4] 2> 19155 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:delete cxid:0xa1 zxid:0xad txntype:-1 reqpath:n/a Error Path:/solr/collections/onenodecollection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/onenodecollection/leaders
[junit4:junit4] 2> 19156 T2602 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 19157 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:create cxid:0xa2 zxid:0xae txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 19158 T2602 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 19159 T2602 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 19160 T2602 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58579/dms/u/onenodecollectioncore/
[junit4:junit4] 2> 19160 T2602 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 19161 T2602 oasc.SyncStrategy.syncToMe http://127.0.0.1:58579/dms/u/onenodecollectioncore/ has no replicas
[junit4:junit4] 2> 19161 T2602 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58579/dms/u/onenodecollectioncore/
[junit4:junit4] 2> 19162 T2602 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4] 2> 19165 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:create cxid:0xac zxid:0xb2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> C215_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:45522/dms/u, state=recovering, node_name=127.0.0.1:45522_dms%2Fu, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 19702 T2640 C215 P45522 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58579/dms/u/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 19702 T2640 C215 P45522 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:45522/dms/u START replicas=[http://127.0.0.1:58579/dms/u/collection1/] nUpdates=100
[junit4:junit4] 2> 19703 T2640 C215 P45522 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 19703 T2640 C215 P45522 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 19703 T2640 C215 P45522 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 19703 T2640 C215 P45522 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 19704 T2640 C215 P45522 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 19704 T2640 C215 P45522 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58579/dms/u/collection1/. core=collection1
[junit4:junit4] 2> 19704 T2640 C215 P45522 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C216 name=collection1 org.apache.solr.core.SolrCore@af5e1ea4 url=http://127.0.0.1:58579/dms/u/collection1 node=127.0.0.1:58579_dms%2Fu C216_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:58579/dms/u, state=active, node_name=127.0.0.1:58579_dms%2Fu, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 19708 T2601 C216 P58579 REQ /get {getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 19709 T2601 C216 P58579 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 19711 T2601 C216 P58579 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1
[junit4:junit4] 2> 19713 T2601 C216 P58579 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5ef186c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a6d29fcd; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 19713 T2601 C216 P58579 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 19714 T2601 C216 P58579 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5ef186c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a6d29fcd; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5ef186c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a6d29fcd; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 19715 T2601 C216 P58579 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 19716 T2601 C216 P58579 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1
[junit4:junit4] 2> 19717 T2601 C216 P58579 oass.SolrIndexSearcher.<init> Opening Searcher@7ba6d68f realtime
[junit4:junit4] 2> 19717 T2601 C216 P58579 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 19718 T2601 C216 P58579 /update {softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 9
[junit4:junit4] 2> 19719 T2640 C215 P45522 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 19719 T2640 C215 P45522 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 19721 T2600 C216 P58579 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 19721 T2600 C216 P58579 REQ /replication {qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 19722 T2640 C215 P45522 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 19723 T2640 C215 P45522 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 19723 T2640 C215 P45522 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 19725 T2601 C216 P58579 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1
[junit4:junit4] 2> 19725 T2601 C216 P58579 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index
[junit4:junit4] 2> 19726 T2601 C216 P58579 REQ /replication {qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=2
[junit4:junit4] 2> 19727 T2640 C215 P45522 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 19728 T2640 C215 P45522 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index.20130301202321798 forceNew:false
[junit4:junit4] 2> 19728 T2640 C215 P45522 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 19728 T2640 C215 P45522 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/index5598156002tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@93d703f9) fullCopy=false
[junit4:junit4] 2> 19730 T2603 C216 P58579 REQ /replication {checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 19731 T2640 C215 P45522 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index
[junit4:junit4] 2> 19732 T2640 C215 P45522 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 19732 T2640 C215 P45522 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 19733 T2640 C215 P45522 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 19733 T2640 C215 P45522 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 19734 T2640 C215 P45522 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 19734 T2640 C215 P45522 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 19735 T2640 C215 P45522 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7f1deb2d lockFactory=org.apache.lucene.store.NativeFSLockFactory@651abeb7; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7f1deb2d lockFactory=org.apache.lucene.store.NativeFSLockFactory@651abeb7; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 19735 T2640 C215 P45522 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 19736 T2640 C215 P45522 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 19736 T2640 C215 P45522 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 19737 T2640 C215 P45522 oass.SolrIndexSearcher.<init> Opening Searcher@313ed79c main
[junit4:junit4] 2> 19738 T2639 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@313ed79c main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 19738 T2639 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index
[junit4:junit4] 2> 19739 T2640 C215 P45522 oash.SnapPuller.fetchLatestIndex removing temporary index download directory files MockDirWrapper(org.apache.lucene.store.MMapDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/index5598156002tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@93d703f9)
[junit4:junit4] 2> 19739 T2640 C215 P45522 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index.20130301202321798
[junit4:junit4] 2> 19739 T2640 C215 P45522 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index
[junit4:junit4] 2> 19740 T2640 C215 P45522 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 19740 T2640 C215 P45522 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 19740 T2640 C215 P45522 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 19740 T2640 C215 P45522 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 19742 T2640 C215 P45522 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 19929 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19934 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45522/dms/u",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:45522_dms%2Fu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 19945 T2594 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> 19945 T2607 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> 19945 T2622 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> 19945 T2588 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> 19945 T2637 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> 19969 T2602 oasc.ZkController.register We are http://127.0.0.1:58579/dms/u/onenodecollectioncore/ and leader is http://127.0.0.1:58579/dms/u/onenodecollectioncore/
[junit4:junit4] 2> 19970 T2602 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:58579/dms/u
[junit4:junit4] 2> 19971 T2602 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 19971 T2602 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4] 2> 19973 T2602 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19975 T2566 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 19976 T2566 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20977 T2566 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21451 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21452 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58579/dms/u",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58579_dms%2Fu",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 21457 T2594 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> 21457 T2622 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> 21457 T2607 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> 21457 T2637 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> 21457 T2588 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> 21979 T2566 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21980 T2566 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4] 2> 21980 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> C215_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:45522/dms/u, state=active, node_name=127.0.0.1:45522_dms%2Fu, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 21991 T2633 C215 P45522 /update {update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58579/dms/u/collection1/&version=2&wt=javabin} {add=[1 (1428349469650321408)]} 0 0
[junit4:junit4] 2> 21992 T2602 C216 P58579 /update {version=2&wt=javabin} {add=[1 (1428349469650321408)]} 0 5
[junit4:junit4] 2> 21995 T2600 C216 P58579 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 21998 T2600 C216 P58579 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5ef186c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a6d29fcd; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@5ef186c3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a6d29fcd; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_3,generation=3,filenames=[_0_dv.cfs, _0_Lucene40_0.prx, _0_Lucene40_0.tim, _0.fnm, _0_Lucene40_0.tip, _0_nrm.cfe, _0.si, segments_3, _0_Lucene40_0.frq, _0_dv.cfe, _0.fdt, _0_nrm.cfs, _0.fdx]
[junit4:junit4] 2> 21998 T2600 C216 P58579 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0_dv.cfs, _0_Lucene40_0.prx, _0_Lucene40_0.tim, _0.fnm, _0_Lucene40_0.tip, _0_nrm.cfe, _0.si, segments_3, _0_Lucene40_0.frq, _0_dv.cfe, _0.fdt, _0_nrm.cfs, _0.fdx]
[junit4:junit4] 2> 21999 T2600 C216 P58579 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1
[junit4:junit4] 2> 22000 T2600 C216 P58579 oass.SolrIndexSearcher.<init> Opening Searcher@d664000 main
[junit4:junit4] 2> 22001 T2600 C216 P58579 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index
[junit4:junit4] 2> 22002 T2600 C216 P58579 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22002 T2609 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d664000 main{StandardDirectoryReader(segments_3:3:nrt _0(5.0):C1)}
[junit4:junit4] 2> 22003 T2609 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index
[junit4:junit4] 2> 22003 T2600 C216 P58579 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:45522/dms/u/collection1/, StdNode: http://127.0.0.1:37469/dms/u/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 22005 T2631 C215 P45522 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22007 T2631 C215 P45522 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7f1deb2d lockFactory=org.apache.lucene.store.NativeFSLockFactory@651abeb7; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@7f1deb2d lockFactory=org.apache.lucene.store.NativeFSLockFactory@651abeb7; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_3,generation=3,filenames=[_0_dv.cfs, _0_Lucene40_0.prx, _0_Lucene40_0.tim, _0.fnm, _0_Lucene40_0.tip, _0_nrm.cfe, _0.si, segments_3, _0_Lucene40_0.frq, _0_dv.cfe, _0.fdt, _0_nrm.cfs, _0.fdx]
[junit4:junit4] 2> 22008 T2631 C215 P45522 oasc.SolrDeletionPolicy.updateCommits newest commit = 3[_0_dv.cfs, _0_Lucene40_0.prx, _0_Lucene40_0.tim, _0.fnm, _0_Lucene40_0.tip, _0_nrm.cfe, _0.si, segments_3, _0_Lucene40_0.frq, _0_dv.cfe, _0.fdt, _0_nrm.cfs, _0.fdx]
[junit4:junit4] 2> ASYNC NEW_CORE C217 name=collection1 org.apache.solr.core.SolrCore@e149423c url=http://127.0.0.1:37469/dms/u/collection1 node=127.0.0.1:37469_dms%2Fu C217_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:37469/dms/u, state=active, node_name=127.0.0.1:37469_dms%2Fu, collection=collection1, shard=shard2, core=collection1, leader=true}
[junit4:junit4] 2> 22008 T2616 C217 P37469 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 22008 T2631 C215 P45522 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 22009 T2616 C217 P37469 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2
[junit4:junit4] 2> 22009 T2631 C215 P45522 oass.SolrIndexSearcher.<init> Opening Searcher@d0621067 main
[junit4:junit4] 2> 22010 T2631 C215 P45522 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22010 T2616 C217 P37469 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@c84d9342 lockFactory=org.apache.lucene.store.NativeFSLockFactory@b3e98722; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> 22011 T2639 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d0621067 main{StandardDirectoryReader(segments_3:3:nrt _0(5.0):C1)}
[junit4:junit4] 2> 22011 T2616 C217 P37469 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4] 2> 22012 T2639 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index
[junit4:junit4] 2> 22012 T2616 C217 P37469 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@c84d9342 lockFactory=org.apache.lucene.store.NativeFSLockFactory@b3e98722; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4] 2> commit{dir=MockDirWrapper(NRTCachingDirectory(org.apache.lucene.store.RAMDirectory@c84d9342 lockFactory=org.apache.lucene.store.NativeFSLockFactory@b3e98722; maxCacheMB=0.2138671875 maxMergeSizeMB=0.8203125)),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4] 2> 22012 T2631 C215 P45522 /update {softCommit=false&expungeDeletes=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 7
[junit4:junit4] 2> 22013 T2616 C217 P37469 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4] 2> 22014 T2616 C217 P37469 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2
[junit4:junit4] 2> 22014 T2616 C217 P37469 oass.SolrIndexSearcher.<init> Opening Searcher@7960b6bb main
[junit4:junit4] 2> 22015 T2616 C217 P37469 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 22015 T2624 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7960b6bb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 22016 T2624 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/index
[junit4:junit4] 2> 22016 T2616 C217 P37469 /update {softCommit=false&expungeDeletes=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 8
[junit4:junit4] 2> 22017 T2600 C216 P58579 /update {softCommit=false&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 22
[junit4:junit4] 2> 22021 T2615 C217 P37469 REQ /select {q=*:*&start=0&isShard=true&distrib=false&NOW=1362180204091&fl=id,score&version=2&fsv=true&rows=10&wt=javabin&shard.url=127.0.0.1:37469/dms/u/collection1/} hits=0 status=0 QTime=0
[junit4:junit4] 2> 22022 T2632 C215 P45522 REQ /select {q=*:*&start=0&isShard=true&distrib=false&NOW=1362180204091&fl=id,score&version=2&fsv=true&rows=10&wt=javabin&shard.url=127.0.0.1:58579/dms/u/collection1/|127.0.0.1:45522/dms/u/collection1/} hits=1 status=0 QTime=0
[junit4:junit4] 2> 22024 T2633 C215 P45522 REQ /select {q=*:*&isShard=true&distrib=false&NOW=1362180204091&version=2&ids=1&wt=javabin&shard.url=127.0.0.1:58579/dms/u/collection1/|127.0.0.1:45522/dms/u/collection1/} status=0 QTime=0
[junit4:junit4] 2> 22025 T2601 C216 P58579 REQ /select {q=*:*&version=2&wt=javabin} hits=1 status=0 QTime=5
[junit4:junit4] 2> 22026 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C218 name=onenodecollectioncore org.apache.solr.core.SolrCore@85158f31 url=http://127.0.0.1:58579/dms/u/onenodecollectioncore node=127.0.0.1:58579_dms%2Fu C218_STATE=coll:onenodecollection core:onenodecollectioncore props:{base_url=http://127.0.0.1:58579/dms/u, state=active, node_name=127.0.0.1:58579_dms%2Fu, roles=none, collection=onenodecollection, shard=shard1, core=onenodecollectioncore, leader=true}
[junit4:junit4] 2> 22034 T2603 C218 P58579 REQ /select {q=*:*&version=2&wt=javabin} hits=0 status=0 QTime=0
[junit4:junit4] 2> 22035 T2566 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:51525 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@3a6a8f0f
[junit4:junit4] 2> 22038 T2649 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:51525. Will not attempt to authenticate using SASL (Access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4] 2> 22038 T2566 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 22038 T2649 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:51525, initiating session
[junit4:junit4] 2> 22038 T2568 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:41365
[junit4:junit4] 2> 22039 T2568 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:41365
[junit4:junit4] 2> 22040 T2570 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d28441041000b with negotiated timeout 10000 for client /127.0.0.1:41365
[junit4:junit4] 2> 22040 T2649 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:51525, sessionid = 0x13d28441041000b, negotiated timeout = 10000
[junit4:junit4] 2> 22040 T2650 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a6a8f0f name:ZooKeeperConnection Watcher:127.0.0.1:51525 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 22041 T2566 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 22068 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d28441041000b
[junit4:junit4] 2> 22068 T2650 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 22068 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41365 which had sessionid 0x13d28441041000b
[junit4:junit4] 2> 22068 T2566 oaz.ZooKeeper.close Session: 0x13d28441041000b closed
[junit4:junit4] 2> 22069 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d284410410004
[junit4:junit4] 2> 22070 T2594 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 22070 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41325 which had sessionid 0x13d284410410004
[junit4:junit4] 2> 22070 T2566 oaz.ZooKeeper.close Session: 0x13d284410410004 closed
[junit4:junit4] 2> 22074 T2566 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 57831
[junit4:junit4] 2> 22075 T2566 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=870037408
[junit4:junit4] 2> 22961 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22962 T2589 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57831/dms/u",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:57831_dms%2Fu_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:57831_dms%2Fu",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 22965 T2588 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> 22965 T2622 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> 22965 T2637 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> 22965 T2607 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> 24076 T2566 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@5e85851
[junit4:junit4] 2> 24078 T2566 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index
[junit4:junit4] 2> 24079 T2566 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 24081 T2566 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 24081 T2566 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 24082 T2566 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 24082 T2566 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 24083 T2566 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 24084 T2566 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data/index
[junit4:junit4] 2> 24084 T2566 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data
[junit4:junit4] 2> 24085 T2566 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data
[junit4:junit4] 2> 24085 T2566 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data/index
[junit4:junit4] 2> 24086 T2566 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/control/data/index
[junit4:junit4] 2> 24086 T2589 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89271840412860419-127.0.0.1:57831_dms%2Fu-n_0000000000) am no longer a leader.
[junit4:junit4] 2> 24086 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d284410410003
[junit4:junit4] 2> 24087 T2622 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> 24088 T2637 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> 24088 T2607 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> 24088 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41322 which had sessionid 0x13d284410410003
[junit4:junit4] 2> 24088 T2566 oaz.ZooKeeper.close Session: 0x13d284410410003 closed
[junit4:junit4] 2> 24090 T2607 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 24090 T2622 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 24090 T2637 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 24090 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:delete cxid:0xbc zxid:0xcd txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 24091 T2607 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 24093 T2607 oasc.Overseer.start Overseer (id=89271840412860422-127.0.0.1:58579_dms%2Fu-n_0000000001) starting
[junit4:junit4] 2> 24093 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:create cxid:0xc1 zxid:0xcf txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 24094 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:create cxid:0xc2 zxid:0xd0 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 24095 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:create cxid:0xc3 zxid:0xd1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 24097 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410006 type:create cxid:0xc4 zxid:0xd2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 24098 T2652 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 24099 T2651 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 24109 T2566 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/dms/u,null}
[junit4:junit4] 2> 24161 T2566 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 58579
[junit4:junit4] 2> 24162 T2566 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-44108160
[junit4:junit4] 2> 25388 T2588 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 25388 T2588 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> 25388 T2588 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 25389 T2588 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 25602 T2651 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 25602 T2651 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58579/dms/u",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58579_dms%2Fu_onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:58579_dms%2Fu",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 25605 T2651 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58579/dms/u",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58579_dms%2Fu_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:58579_dms%2Fu",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 25607 T2622 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> 25607 T2607 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> 25607 T2637 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> 27165 T2566 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@af5e1ea4
[junit4:junit4] 2> 27168 T2566 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index
[junit4:junit4] 2> 27169 T2566 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 27172 T2566 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=1,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 27172 T2566 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 27173 T2566 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 27174 T2566 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> C216_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:58579/dms/u, state=down, node_name=127.0.0.1:58579_dms%2Fu, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 27175 T2566 C216 P58579 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index
[junit4:junit4] 2> 27177 T2566 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 27177 T2566 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index
[junit4:junit4] 2> 27178 T2566 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index
[junit4:junit4] 2> 27179 T2566 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1/index
[junit4:junit4] 2> 27180 T2566 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1
[junit4:junit4] 2> 27180 T2566 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty1
[junit4:junit4] 2> 27181 T2566 oasc.SolrCore.close [onenodecollectioncore] CLOSING SolrCore org.apache.solr.core.SolrCore@85158f31
[junit4:junit4] 2> 27187 T2566 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 27188 T2566 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 27189 T2566 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 27189 T2566 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 27190 T2566 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4] 2> 27191 T2566 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection/index
[junit4:junit4] 2> 27192 T2566 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection/index
[junit4:junit4] 2> 27193 T2566 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection/index
[junit4:junit4] 2> 27193 T2566 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection
[junit4:junit4] 2> 27194 T2566 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1362180182075/onenodecollection
[junit4:junit4] 2> 27195 T2651 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89271840412860422-127.0.0.1:58579_dms%2Fu-n_0000000001) am no longer a leader.
[junit4:junit4] 2> 27195 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d284410410006
[junit4:junit4] 2> 27197 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41327 which had sessionid 0x13d284410410006
[junit4:junit4] 2> 27197 T2607 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> 27197 T2566 oaz.ZooKeeper.close Session: 0x13d284410410006 closed
[junit4:junit4] 2> 27197 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:delete cxid:0x53 zxid:0xdd txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard1 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard1
[junit4:junit4] 2> 27198 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:delete cxid:0x6e zxid:0xde txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 27197 T2607 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 27198 T2637 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 27198 T2607 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 27199 T2622 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 27199 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:create cxid:0x54 zxid:0xdf txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 27199 T2607 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 27201 T2637 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 27201 T2637 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 27201 T2622 oasc.Overseer.start Overseer (id=89271840412860424-127.0.0.1:37469_dms%2Fu-n_0000000002) starting
[junit4:junit4] 2> 27201 T2637 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 27202 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:create cxid:0x73 zxid:0xe2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 27202 T2637 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:45522/dms/u/collection1/
[junit4:junit4] 2> 27202 T2637 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:45522/dms/u START replicas=[http://127.0.0.1:58579/dms/u/collection1/] nUpdates=100
[junit4:junit4] 2> 27202 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:create cxid:0x74 zxid:0xe3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 27203 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:create cxid:0x75 zxid:0xe4 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 27204 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d284410410008 type:create cxid:0x76 zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 27205 T2622 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> 27205 T2655 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 27205 T2654 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 27207 T2622 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 27208 T2654 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 27208 T2637 oasu.PeerSync.handleResponse WARNING PeerSync: core=collection1 url=http://127.0.0.1:45522/dms/u couldn't connect to http://127.0.0.1:58579/dms/u/collection1/, counting as success
[junit4:junit4] 2> 27209 T2637 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:45522/dms/u DONE. sync succeeded
[junit4:junit4] 2> 27209 T2637 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 27209 T2637 oasc.SyncStrategy.syncToMe http://127.0.0.1:45522/dms/u/collection1/: try and ask http://127.0.0.1:58579/dms/u/collection1/ to sync
[junit4:junit4] 2> 27210 T2637 oasc.SolrException.log SEVERE Sync request error: org.apache.solr.client.solrj.SolrServerException: Server refused connection at: http://127.0.0.1:58579/dms/u/collection1
[junit4:junit4] 2> 27210 T2637 oasc.SyncStrategy.syncToMe http://127.0.0.1:45522/dms/u/collection1/: Sync failed - asking replica (http://127.0.0.1:58579/dms/u/collection1/) to recover.
[junit4:junit4] 2> 27211 T2637 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:45522/dms/u/collection1/
[junit4:junit4] 2> 27211 T2658 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 27211 T2622 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> 27211 T2637 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 27216 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:create cxid:0x5c zxid:0xeb txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 27216 T2658 oasc.SolrException.log SEVERE http://127.0.0.1:45522/dms/u/collection1/: Could not tell a replica to recover:org.apache.solr.client.solrj.SolrServerException: Server refused connection at: http://127.0.0.1:58579/dms/u
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:409)
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
[junit4:junit4] 2> at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:298)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1121)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:614)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] 2> Caused by: org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:58579 refused
[junit4:junit4] 2> at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:190)
[junit4:junit4] 2> at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
[junit4:junit4] 2> at org.apache.http.impl.client.DefaultRequestDirector.tryConnect(DefaultRequestDirector.java:645)
[junit4:junit4] 2> at org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:480)
[junit4:junit4] 2> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:906)
[junit4:junit4] 2> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:805)
[junit4:junit4] 2> at org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:784)
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:353)
[junit4:junit4] 2> ... 5 more
[junit4:junit4] 2> Caused by: java.net.ConnectException: Connection refused
[junit4:junit4] 2> at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:369)
[junit4:junit4] 2> at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:230)
[junit4:junit4] 2> at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:212)
[junit4:junit4] 2> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:402)
[junit4:junit4] 2> at java.net.Socket.connect(Socket.java:590)
[junit4:junit4] 2> at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
[junit4:junit4] 2> at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
[junit4:junit4] 2> ... 12 more
[junit4:junit4] 2>
[junit4:junit4] 2> 27217 T2637 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> 27218 T2637 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 27218 T2637 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> 27218 T2566 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/dms/u,null}
[junit4:junit4] 2> 27271 T2566 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 37469
[junit4:junit4] 2> 27271 T2566 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-350454147
[junit4:junit4] 2> 28273 T2566 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@e149423c
[junit4:junit4] 2> 28275 T2566 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3/index
[junit4:junit4] 2> 28277 T2566 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty3
[junit4:junit4] 2> 28279 T2566 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 28279 T2566 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 28280 T2566 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 28281 T2566 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 28282 T2566 C217 P37469 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/index
[junit4:junit4] 2> 28283 T2566 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 28283 T2566 oasc.CachingDirectoryFactory.close Releasing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/index
[junit4:junit4] 2> 28284 T2566 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2
[junit4:junit4] 2> 28284 T2566 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2
[junit4:junit4] 2> 28285 T2566 oasc.CachingDirectoryFactory.close Closing directory when closing factory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/index
[junit4:junit4] 2> 28285 T2566 oasc.CachingDirectoryFactory.closeDirectory Closing directory:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-1362180182075/jetty2/index
[junit4:junit4] 2> 28286 T2654 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89271840412860424-127.0.0.1:37469_dms%2Fu-n_0000000002) am no longer a leader.
[junit4:junit4] 2> 28286 T2571 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d284410410008
[junit4:junit4] 2> 28287 T2622 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> 28287 T2568 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:41331 which had sessionid 0x13d284410410008
[junit4:junit4] 2> 28287 T2566 oaz.ZooKeeper.close Session: 0x13d284410410008 closed
[junit4:junit4] 2> 28287 T2622 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 28288 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:delete cxid:0x64 zxid:0xef txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4] 2> 28289 T2622 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 28289 T2622 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4] 2> 28289 T2637 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 28291 T2637 oasc.Overseer.start Overseer (id=89271840412860426-127.0.0.1:45522_dms%2Fu-n_0000000003) starting
[junit4:junit4] 2> 28291 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:create cxid:0x69 zxid:0xf1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 28292 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:create cxid:0x6a zxid:0xf2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 28293 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:create cxid:0x6b zxid:0xf3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 28293 T2571 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d28441041000a type:create cxid:0x6c zxid:0xf4 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4] 2> 28294 T2637 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> 28294 T2660 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 28296 T2659 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 28296 T2637 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4] 2> 28297 T2659 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 28299 T2659 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37469/dms/u",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:37469_dms%2Fu_collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:37469_dms%2Fu",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 28302 T2637 oascc.ZkStateReader$
[...truncated too long message...]
it4:junit4] > at org.junit.Assert.failNotEquals(Assert.java:647)
[junit4:junit4] > at org.junit.Assert.assertEquals(Assert.java:128)
[junit4:junit4] > at org.junit.Assert.assertEquals(Assert.java:472)
[junit4:junit4] > at org.junit.Assert.assertEquals(Assert.java:456)
[junit4:junit4] > at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:209)
[junit4:junit4] > at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:89)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
[junit4:junit4] > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4:junit4] > at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
[junit4:junit4] > at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
[junit4:junit4] > at java.lang.reflect.Method.invoke(Method.java:613)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4] > at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
[junit4:junit4] > at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
[junit4:junit4] > at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4] > at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
[junit4:junit4] > at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4] > at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4] > at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4] > at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4] > at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4] > at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4] > at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] > at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] 2> 29476 T2566 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 29480 T2565 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 29929 T2569 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4] 2> NOTE: test params are: codec=Lucene40, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=el, timezone=America/Argentina/Mendoza
[junit4:junit4] 2> NOTE: Linux 3.2.0-38-generic x86/IBM Corporation 1.7.0 (32-bit)/cpus=8,threads=3,free=90226448,total=219611136
[junit4:junit4] 2> NOTE: All tests run in this JVM: [NotRequiredUniqueKeyTest, DirectSolrSpellCheckerTest, TestPluginEnable, ChaosMonkeyNothingIsSafeTest, SignatureUpdateProcessorFactoryTest, TestHashPartitioner, CollectionsAPIDistributedZkTest, LukeRequestHandlerTest, EchoParamsTest, BinaryUpdateRequestHandlerTest, BasicFunctionalityTest, FullSolrCloudDistribCmdsTest, TestSuggestSpellingConverter, SliceStateUpdateTest, ConvertedLegacyTest, StatelessScriptUpdateProcessorFactoryTest, SliceStateTest, FieldAnalysisRequestHandlerTest, TestReversedWildcardFilterFactory, ResourceLoaderTest, TestFastOutputStream, TestPartialUpdateDeduplication, TestZkChroot, TestNumberUtils, NoCacheHeaderTest, TestStressVersions, TestQueryTypes, StandardRequestHandlerTest, TestFunctionQuery, TestLRUCache, TestDistributedGrouping, ZkSolrClientTest, TestAnalyzedSuggestions, TestDistributedSearch, TestSolr4Spatial, CircularListTest, TestIBSimilarityFactory, QueryEqualityTest, TestRemoteStreaming, TermVectorComponentDistributedTest, HardAutoCommitTest, BasicZkTest, TestDocSet, IndexSchemaRuntimeFieldTest, TestFastLRUCache, TestSolrDeletionPolicy1, TestJmxIntegration, StatsComponentTest, TestFastWriter, TestCollationField, TestRandomDVFaceting, TestLMJelinekMercerSimilarityFactory, PathHierarchyTokenizerFactoryTest, TestRealTimeGet, CSVRequestHandlerTest, TestQuerySenderNoQuery, TestQueryUtils, JsonLoaderTest, TestLuceneMatchVersion, TestRecovery, TestTrie, TestMultiCoreConfBootstrap, TestPropInjectDefaults, TestSolrDeletionPolicy2, BasicDistributedZkTest, RecoveryZkTest, LeaderElectionIntegrationTest, DistributedTermsComponentTest, DirectUpdateHandlerTest, TestCoreContainer, TestSort, SortByFunctionTest, TestBinaryResponseWriter, SampleTest, TestIndexSearcher, SolrRequestParserTest, TestWordDelimiterFilterFactory, TestCSVLoader, DocumentBuilderTest, DistributedQueryElevationComponentTest, TestPHPSerializedResponseWriter, TermVectorComponentTest, DocumentAnalysisRequestHandlerTest, TestSolrQueryParser, RequestHandlersTest, RequiredFieldsTest, CopyFieldTest, SuggesterTSTTest, SuggesterTest, TestFoldingMultitermQuery, UpdateRequestProcessorFactoryTest, TestPropInject, TestWriterPerf, AlternateDirectoryTest, BadComponentTest, TestUpdate, TestMergePolicyConfig, TestLFUCache, TestQuerySenderListener, SolrIndexConfigTest, NumericFieldsTest, MultiTermTest, TestConfig, TestPhraseSuggestions, TestPerFieldSimilarity, TestCodecSupport, URLClassifyProcessorTest, OpenExchangeRatesOrgProviderTest, DateFieldTest, TestBadConfig, UUIDFieldTest, SystemInfoHandlerTest, TestUtils, ZkNodePropsTest, AnalysisAfterCoreReloadTest, TestDocumentBuilder, TestCharFilters, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 30.00s, 1 test, 1 failure <<< FAILURES!
[...truncated 74 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:381: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:374: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:183: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:449: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1207: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:870: There were test failures: 259 suites, 1085 tests, 1 failure, 10 ignored (4 assumptions)
Total time: 46 minutes 17 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 32bit/ibm-j9-jdk7
Email was triggered for: Failure
Sending email for trigger: Failure