lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Policeman Jenkins Server <jenk...@thetaphi.de>
Subject [JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.8.0-ea-b79) - Build # 4811 - Failure!
Date Thu, 21 Mar 2013 17:54:42 GMT
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/4811/
Java: 32bit/jdk1.8.0-ea-b79 -client -XX:+UseSerialGC

2 tests failed.
REGRESSION:  org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch

Error Message:
Server at http://127.0.0.1:39192/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update

Stack Trace:
org.apache.solr.common.SolrException: Server at http://127.0.0.1:39192/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
	at __randomizedtesting.SeedInfo.seed([87929F081E7A37E7:6741110692557DB]:0)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:375)
	at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:181)
	at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
	at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
	at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:196)
	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:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:487)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:722)


REGRESSION:  org.apache.solr.cloud.UnloadDistributedZkTest.testDistribSearch

Error Message:
Still found shard2 in collection test_unload_shard_and_collection

Stack Trace:
java.lang.AssertionError: Still found shard2 in collection test_unload_shard_and_collection
	at __randomizedtesting.SeedInfo.seed([87929F081E7A37E7:6741110692557DB]:0)
	at org.junit.Assert.fail(Assert.java:93)
	at org.apache.solr.cloud.UnloadDistributedZkTest.testUnloadShardAndCollection(UnloadDistributedZkTest.java:124)
	at org.apache.solr.cloud.UnloadDistributedZkTest.doTest(UnloadDistributedZkTest.java:77)
	at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:806)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:487)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
	at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
	at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
	at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
	at java.lang.Thread.run(Thread.java:722)




Build Log:
[...truncated 9320 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4]   2> 0 T1984 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4]   2> 3 T1984 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-1363887878822
[junit4:junit4]   2> 4 T1984 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4]   2> 4 T1985 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4]   2> 6 T1985 oazs.ZooKeeperServer.setTickTime tickTime set to 1000
[junit4:junit4]   2> 6 T1985 oazs.ZooKeeperServer.setMinSessionTimeout minSessionTimeout set to -1
[junit4:junit4]   2> 6 T1985 oazs.ZooKeeperServer.setMaxSessionTimeout maxSessionTimeout set to -1
[junit4:junit4]   2> 7 T1985 oazs.NIOServerCnxnFactory.configure binding to port 0.0.0.0/0.0.0.0:0
[junit4:junit4]   2> 8 T1985 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-1363887878822/zookeeper/server1/data/version-2/snapshot.0
[junit4:junit4]   2> 104 T1984 oasc.ZkTestServer.run start zk server on port:50428
[junit4:junit4]   2> 105 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1a6c752
[junit4:junit4]   2> 105 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 106 T1990 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 106 T1990 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 106 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54151
[junit4:junit4]   2> 107 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54151
[junit4:junit4]   2> 108 T1988 oazsp.FileTxnLog.append Creating new log file: log.1
[junit4:junit4]   2> 177 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac0000 with negotiated timeout 10000 for client /127.0.0.1:54151
[junit4:junit4]   2> 177 T1990 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac0000, negotiated timeout = 10000
[junit4:junit4]   2> 178 T1991 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a6c752 name:ZooKeeperConnection Watcher:127.0.0.1:50428 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 179 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 179 T1984 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4]   2> 184 T1989 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8e0d72ac0000
[junit4:junit4]   2> 185 T1991 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 186 T1986 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54151 which had sessionid 0x13d8e0d72ac0000
[junit4:junit4]   2> 185 T1984 oaz.ZooKeeper.close Session: 0x13d8e0d72ac0000 closed
[junit4:junit4]   2> 187 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@16123d6
[junit4:junit4]   2> 188 T1992 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 188 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 189 T1992 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 189 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54152
[junit4:junit4]   2> 189 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54152
[junit4:junit4]   2> 191 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac0001 with negotiated timeout 10000 for client /127.0.0.1:54152
[junit4:junit4]   2> 191 T1992 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac0001, negotiated timeout = 10000
[junit4:junit4]   2> 192 T1993 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16123d6 name:ZooKeeperConnection Watcher:127.0.0.1:50428/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 192 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 193 T1984 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4]   2> 199 T1984 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4]   2> 203 T1984 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4]   2> 206 T1984 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4]   2> 211 T1984 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> 211 T1984 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4]   2> 218 T1984 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> 220 T1984 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4]   2> 225 T1984 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> 226 T1984 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4]   2> 230 T1984 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> 230 T1984 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4]   2> 235 T1984 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> 236 T1984 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4]   2> 241 T1984 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> 242 T1984 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4]   2> 245 T1984 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> 246 T1984 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4]   2> 251 T1984 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> 251 T1984 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4]   2> 256 T1984 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> 257 T1984 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4]   2> 262 T1989 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8e0d72ac0001
[junit4:junit4]   2> 263 T1993 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 263 T1986 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54152 which had sessionid 0x13d8e0d72ac0001
[junit4:junit4]   2> 263 T1984 oaz.ZooKeeper.close Session: 0x13d8e0d72ac0001 closed
[junit4:junit4]   2> 330 T1984 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 337 T1984 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46693
[junit4:junit4]   2> 337 T1984 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 337 T1984 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 338 T1984 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-1363887879084
[junit4:junit4]   2> 338 T1984 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1363887879084/solr.xml
[junit4:junit4]   2> 338 T1984 oasc.CoreContainer.<init> New CoreContainer 11214518
[junit4:junit4]   2> 339 T1984 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-1363887879084/'
[junit4:junit4]   2> 339 T1984 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-1363887879084/'
[junit4:junit4]   2> 355 T1984 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 356 T1984 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 356 T1984 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 356 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 357 T1984 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 357 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 357 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 358 T1984 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 358 T1984 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 358 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 365 T1984 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 395 T1984 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:50428/solr
[junit4:junit4]   2> 396 T1984 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 397 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@81914c
[junit4:junit4]   2> 399 T2003 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 399 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 399 T2003 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 400 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54153
[junit4:junit4]   2> 400 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54153
[junit4:junit4]   2> 402 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac0002 with negotiated timeout 20000 for client /127.0.0.1:54153
[junit4:junit4]   2> 402 T2003 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac0002, negotiated timeout = 20000
[junit4:junit4]   2> 402 T2004 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@81914c name:ZooKeeperConnection Watcher:127.0.0.1:50428 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 403 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 406 T1989 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8e0d72ac0002
[junit4:junit4]   2> 407 T2004 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 407 T1986 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54153 which had sessionid 0x13d8e0d72ac0002
[junit4:junit4]   2> 407 T1984 oaz.ZooKeeper.close Session: 0x13d8e0d72ac0002 closed
[junit4:junit4]   2> 408 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 413 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@15814d9
[junit4:junit4]   2> 415 T2005 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 415 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 416 T2005 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 416 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54154
[junit4:junit4]   2> 417 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54154
[junit4:junit4]   2> 418 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac0003 with negotiated timeout 20000 for client /127.0.0.1:54154
[junit4:junit4]   2> 418 T2005 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac0003, negotiated timeout = 20000
[junit4:junit4]   2> 418 T2006 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15814d9 name:ZooKeeperConnection Watcher:127.0.0.1:50428/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 419 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 422 T1984 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4]   2> 427 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0003 type:create cxid:0x7 zxid:0x1b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 429 T1984 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4]   2> 434 T1984 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4]   2> 437 T1984 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46693_
[junit4:junit4]   2> 438 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0003 type:delete cxid:0x12 zxid:0x1e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:46693_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:46693_
[junit4:junit4]   2> 439 T1984 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46693_
[junit4:junit4]   2> 444 T1984 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4]   2> 453 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0003 type:delete cxid:0x20 zxid:0x23 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 454 T1984 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 458 T1984 oasc.Overseer.start Overseer (id=89383756026871811-127.0.0.1:46693_-n_0000000000) starting
[junit4:junit4]   2> 459 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0003 type:create cxid:0x25 zxid:0x25 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 461 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0003 type:create cxid:0x26 zxid:0x26 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 463 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0003 type:create cxid:0x28 zxid:0x27 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 465 T1984 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4]   2> 470 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0003 type:create cxid:0x2e zxid:0x29 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 472 T2008 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 474 T1984 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4]   2> 478 T1984 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4]   2> 481 T1984 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 485 T2007 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 491 T2009 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-1363887879084/collection1
[junit4:junit4]   2> 491 T2009 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4]   2> 492 T2009 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 493 T2009 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4]   2> 495 T2009 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-1363887879084/collection1/'
[junit4:junit4]   2> 496 T2009 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-1363887879084/collection1/lib/README' to classloader
[junit4:junit4]   2> 496 T2009 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-1363887879084/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 538 T2009 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 582 T2009 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 584 T2009 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 589 T2009 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 1031 T2009 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 1037 T2009 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 1039 T2009 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 1056 T2009 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1061 T2009 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 1064 T2009 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1066 T2009 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1066 T2009 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 1066 T2009 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 1068 T2009 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 1068 T2009 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 1068 T2009 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1069 T2009 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-1363887879084/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/control/data/
[junit4:junit4]   2> 1069 T2009 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@ff6818
[junit4:junit4]   2> 1070 T2009 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 1070 T2009 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/control/data forceNew: false
[junit4:junit4]   2> 1071 T2009 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/control/data/index/
[junit4:junit4]   2> 1071 T2009 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/control/data/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 1072 T2009 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/control/data/index forceNew: false
[junit4:junit4]   2> 1074 T2009 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@fd0d54 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1494086),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 1074 T2009 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 1077 T2009 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 1077 T2009 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 1078 T2009 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 1078 T2009 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 1079 T2009 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 1079 T2009 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 1080 T2009 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 1081 T2009 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 1081 T2009 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 1086 T2009 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 1089 T2009 oass.SolrIndexSearcher.<init> Opening Searcher@78c8bb main
[junit4:junit4]   2> 1090 T2009 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/control/data/tlog
[junit4:junit4]   2> 1090 T2009 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 1090 T2009 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 1095 T2010 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@78c8bb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 1096 T2009 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 1096 T2009 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 1992 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 1993 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:46693",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:46693_"}
[junit4:junit4]   2> 1994 T2007 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4]   2> 1994 T2007 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 2001 T2006 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> 2098 T2009 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 2098 T2009 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46693 collection:control_collection shard:shard1
[junit4:junit4]   2> 2100 T2009 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4]   2> 2111 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0003 type:delete cxid:0x82 zxid:0x35 txntype:-1 reqpath:n/a Error Path:/solr/collections/control_collection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/control_collection/leaders
[junit4:junit4]   2> 2112 T2009 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 2112 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0003 type:create cxid:0x83 zxid:0x36 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 2115 T2009 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 2115 T2009 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 2115 T2009 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46693/collection1/
[junit4:junit4]   2> 2116 T2009 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 2116 T2009 oasc.SyncStrategy.syncToMe http://127.0.0.1:46693/collection1/ has no replicas
[junit4:junit4]   2> 2116 T2009 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46693/collection1/
[junit4:junit4]   2> 2117 T2009 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4]   2> 2122 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0003 type:create cxid:0x8e zxid:0x3a txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3509 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3523 T2006 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> 3531 T2009 oasc.ZkController.register We are http://127.0.0.1:46693/collection1/ and leader is http://127.0.0.1:46693/collection1/
[junit4:junit4]   2> 3531 T2009 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46693
[junit4:junit4]   2> 3532 T2009 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 3532 T2009 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 3532 T2009 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 3535 T2009 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 3536 T1984 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 3537 T1984 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 3538 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 3544 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4]   2> 3545 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428/solr sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@f52cce
[junit4:junit4]   2> 3547 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3547 T2012 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3548 T2012 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 3548 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54155
[junit4:junit4]   2> 3549 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54155
[junit4:junit4]   2> 3550 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac0004 with negotiated timeout 10000 for client /127.0.0.1:54155
[junit4:junit4]   2> 3550 T2012 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac0004, negotiated timeout = 10000
[junit4:junit4]   2> 3551 T2013 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f52cce name:ZooKeeperConnection Watcher:127.0.0.1:50428/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3551 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3554 T1984 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 3558 T1984 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4]   2> 3626 T1984 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 3628 T1984 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48206
[junit4:junit4]   2> 3630 T1984 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 3630 T1984 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 3630 T1984 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-1363887882378
[junit4:junit4]   2> 3631 T1984 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1363887882378/solr.xml
[junit4:junit4]   2> 3631 T1984 oasc.CoreContainer.<init> New CoreContainer 2787364
[junit4:junit4]   2> 3631 T1984 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-1363887882378/'
[junit4:junit4]   2> 3632 T1984 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-1363887882378/'
[junit4:junit4]   2> 3648 T1984 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 3648 T1984 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 3648 T1984 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 3649 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 3649 T1984 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 3649 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 3650 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 3650 T1984 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 3650 T1984 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 3651 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 3656 T1984 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 3678 T1984 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:50428/solr
[junit4:junit4]   2> 3679 T1984 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 3679 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@1c82065
[junit4:junit4]   2> 3680 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3680 T2023 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3681 T2023 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 3681 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54156
[junit4:junit4]   2> 3681 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54156
[junit4:junit4]   2> 3682 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac0005 with negotiated timeout 20000 for client /127.0.0.1:54156
[junit4:junit4]   2> 3683 T2023 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac0005, negotiated timeout = 20000
[junit4:junit4]   2> 3683 T2024 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c82065 name:ZooKeeperConnection Watcher:127.0.0.1:50428 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3684 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3686 T1989 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8e0d72ac0005
[junit4:junit4]   2> 3686 T2024 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 3686 T1986 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54156 which had sessionid 0x13d8e0d72ac0005
[junit4:junit4]   2> 3686 T1984 oaz.ZooKeeper.close Session: 0x13d8e0d72ac0005 closed
[junit4:junit4]   2> 3687 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 3692 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1f3bed
[junit4:junit4]   2> 3693 T2025 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 3693 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 3694 T2025 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 3694 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54157
[junit4:junit4]   2> 3695 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54157
[junit4:junit4]   2> 3696 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac0006 with negotiated timeout 20000 for client /127.0.0.1:54157
[junit4:junit4]   2> 3696 T2025 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac0006, negotiated timeout = 20000
[junit4:junit4]   2> 3697 T2026 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f3bed name:ZooKeeperConnection Watcher:127.0.0.1:50428/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 3697 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 3699 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:create cxid:0x1 zxid:0x48 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3701 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:create cxid:0x3 zxid:0x49 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 3705 T1984 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 4710 T1984 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48206_
[junit4:junit4]   2> 4711 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:delete cxid:0xd zxid:0x4a txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:48206_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:48206_
[junit4:junit4]   2> 4712 T1984 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48206_
[junit4:junit4]   2> 4717 T2006 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4]   2> 4718 T2013 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4718 T2026 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4720 T2006 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4]   2> 4727 T2027 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-1363887882378/collection1
[junit4:junit4]   2> 4728 T2027 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 4729 T2027 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 4729 T2027 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 4732 T2027 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-1363887882378/collection1/'
[junit4:junit4]   2> 4732 T2027 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-1363887882378/collection1/lib/README' to classloader
[junit4:junit4]   2> 4733 T2027 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-1363887882378/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 4776 T2027 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 4823 T2027 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 4824 T2027 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 4828 T2027 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 5031 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 5032 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:46693",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:46693_"}
[junit4:junit4]   2> 5036 T2026 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> 5036 T2006 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> 5036 T2013 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> 5271 T2027 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 5276 T2027 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 5279 T2027 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 5294 T2027 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5298 T2027 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 5302 T2027 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5304 T2027 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5304 T2027 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5304 T2027 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 5306 T2027 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 5306 T2027 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 5307 T2027 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5307 T2027 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-1363887882378/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty1/
[junit4:junit4]   2> 5307 T2027 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@ff6818
[junit4:junit4]   2> 5308 T2027 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 5308 T2027 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty1 forceNew: false
[junit4:junit4]   2> 5309 T2027 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty1/index/
[junit4:junit4]   2> 5309 T2027 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 5310 T2027 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty1/index forceNew: false
[junit4:junit4]   2> 5311 T2027 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@110c344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1990969),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 5312 T2027 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 5314 T2027 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 5314 T2027 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 5315 T2027 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 5316 T2027 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 5317 T2027 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 5317 T2027 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 5317 T2027 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 5318 T2027 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 5319 T2027 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 5323 T2027 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 5327 T2027 oass.SolrIndexSearcher.<init> Opening Searcher@1957423 main
[junit4:junit4]   2> 5328 T2027 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty1/tlog
[junit4:junit4]   2> 5328 T2027 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 5329 T2027 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 5335 T2028 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1957423 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 5338 T2027 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 5338 T2027 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 6541 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 6543 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48206",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48206_"}
[junit4:junit4]   2> 6543 T2007 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4]   2> 6544 T2007 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 6552 T2006 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> 6552 T2026 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> 6552 T2013 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> 7341 T2027 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 7341 T2027 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48206 collection:collection1 shard:shard2
[junit4:junit4]   2> 7342 T2027 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4]   2> 7353 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:delete cxid:0x4a zxid:0x5a txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders
[junit4:junit4]   2> 7354 T2027 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 7355 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:create cxid:0x4b zxid:0x5b txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 7358 T2027 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 7359 T2027 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 7359 T2027 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:48206/collection1/
[junit4:junit4]   2> 7360 T2027 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 7360 T2027 oasc.SyncStrategy.syncToMe http://127.0.0.1:48206/collection1/ has no replicas
[junit4:junit4]   2> 7360 T2027 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:48206/collection1/
[junit4:junit4]   2> 7361 T2027 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4]   2> 7367 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:create cxid:0x56 zxid:0x5f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8059 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8072 T2006 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> 8072 T2026 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> 8072 T2013 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> 8123 T2027 oasc.ZkController.register We are http://127.0.0.1:48206/collection1/ and leader is http://127.0.0.1:48206/collection1/
[junit4:junit4]   2> 8124 T2027 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48206
[junit4:junit4]   2> 8124 T2027 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 8125 T2027 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 8125 T2027 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 8127 T2027 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 8129 T1984 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 8130 T1984 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 8131 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 8199 T1984 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 8202 T1984 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:39192
[junit4:junit4]   2> 8204 T1984 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 8205 T1984 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 8205 T1984 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-1363887886956
[junit4:junit4]   2> 8206 T1984 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1363887886956/solr.xml
[junit4:junit4]   2> 8207 T1984 oasc.CoreContainer.<init> New CoreContainer 31502976
[junit4:junit4]   2> 8208 T1984 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-1363887886956/'
[junit4:junit4]   2> 8208 T1984 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-1363887886956/'
[junit4:junit4]   2> 8225 T1984 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 8225 T1984 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 8226 T1984 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 8226 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 8226 T1984 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 8226 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 8227 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 8227 T1984 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 8227 T1984 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 8228 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 8234 T1984 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 8263 T1984 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:50428/solr
[junit4:junit4]   2> 8263 T1984 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 8264 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@d84fde
[junit4:junit4]   2> 8265 T2039 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8265 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8266 T2039 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 8266 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54159
[junit4:junit4]   2> 8267 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54159
[junit4:junit4]   2> 8268 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac0007 with negotiated timeout 20000 for client /127.0.0.1:54159
[junit4:junit4]   2> 8268 T2039 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac0007, negotiated timeout = 20000
[junit4:junit4]   2> 8269 T2040 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d84fde name:ZooKeeperConnection Watcher:127.0.0.1:50428 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8269 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8272 T1989 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8e0d72ac0007
[junit4:junit4]   2> 8273 T1986 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54159 which had sessionid 0x13d8e0d72ac0007
[junit4:junit4]   2> 8273 T2040 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 8273 T1984 oaz.ZooKeeper.close Session: 0x13d8e0d72ac0007 closed
[junit4:junit4]   2> 8274 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 8280 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@9ccd8a
[junit4:junit4]   2> 8281 T2041 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 8281 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 8282 T2041 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 8282 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54160
[junit4:junit4]   2> 8283 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54160
[junit4:junit4]   2> 8284 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac0008 with negotiated timeout 20000 for client /127.0.0.1:54160
[junit4:junit4]   2> 8284 T2041 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac0008, negotiated timeout = 20000
[junit4:junit4]   2> 8285 T2042 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9ccd8a name:ZooKeeperConnection Watcher:127.0.0.1:50428/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 8286 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 8287 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0008 type:create cxid:0x1 zxid:0x6c txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8290 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0008 type:create cxid:0x3 zxid:0x6d txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 8293 T1984 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 9298 T1984 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39192_
[junit4:junit4]   2> 9299 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0008 type:delete cxid:0xd zxid:0x6e txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:39192_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:39192_
[junit4:junit4]   2> 9300 T1984 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:39192_
[junit4:junit4]   2> 9304 T2006 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> 9305 T2026 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> 9306 T2013 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9306 T2042 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9306 T2013 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> 9308 T2006 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9308 T2026 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4]   2> 9316 T2043 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-1363887886956/collection1
[junit4:junit4]   2> 9316 T2043 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 9317 T2043 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 9317 T2043 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 9320 T2043 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-1363887886956/collection1/'
[junit4:junit4]   2> 9321 T2043 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-1363887886956/collection1/lib/README' to classloader
[junit4:junit4]   2> 9321 T2043 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-1363887886956/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 9359 T2043 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 9406 T2043 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 9408 T2043 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 9415 T2043 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 9580 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 9581 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48206",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48206_"}
[junit4:junit4]   2> 9585 T2026 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> 9586 T2013 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> 9586 T2006 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> 9586 T2042 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> 9853 T2043 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 9858 T2043 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 9860 T2043 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 9877 T2043 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9880 T2043 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 9885 T2043 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9886 T2043 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9887 T2043 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9887 T2043 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 9889 T2043 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 9889 T2043 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 9889 T2043 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9890 T2043 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-1363887886956/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty2/
[junit4:junit4]   2> 9890 T2043 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@ff6818
[junit4:junit4]   2> 9890 T2043 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 9891 T2043 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty2 forceNew: false
[junit4:junit4]   2> 9891 T2043 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty2/index/
[junit4:junit4]   2> 9892 T2043 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 9892 T2043 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty2/index forceNew: false
[junit4:junit4]   2> 9894 T2043 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@16382c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1285fd4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 9894 T2043 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 9896 T2043 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 9897 T2043 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 9897 T2043 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 9898 T2043 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 9899 T2043 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 9899 T2043 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 9900 T2043 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 9901 T2043 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 9901 T2043 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 9905 T2043 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 9909 T2043 oass.SolrIndexSearcher.<init> Opening Searcher@1786165 main
[junit4:junit4]   2> 9909 T2043 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty2/tlog
[junit4:junit4]   2> 9910 T2043 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 9910 T2043 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 9916 T2044 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1786165 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 9919 T2043 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 9919 T2043 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 11091 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 11093 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39192",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39192_"}
[junit4:junit4]   2> 11093 T2007 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 11094 T2007 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 11103 T2042 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> 11103 T2006 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> 11103 T2013 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> 11103 T2026 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> 11921 T2043 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 11921 T2043 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:39192 collection:collection1 shard:shard1
[junit4:junit4]   2> 11922 T2043 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4]   2> 11928 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0008 type:delete cxid:0x49 zxid:0x7d txntype:-1 reqpath:n/a Error Path:/solr/collections/collection1/leaders/shard1 Error:KeeperErrorCode = NoNode for /solr/collections/collection1/leaders/shard1
[junit4:junit4]   2> 11929 T2043 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 11930 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0008 type:create cxid:0x4a zxid:0x7e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 11933 T2043 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 11933 T2043 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 11934 T2043 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:39192/collection1/
[junit4:junit4]   2> 11934 T2043 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 11934 T2043 oasc.SyncStrategy.syncToMe http://127.0.0.1:39192/collection1/ has no replicas
[junit4:junit4]   2> 11934 T2043 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:39192/collection1/
[junit4:junit4]   2> 11935 T2043 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4]   2> 11939 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0008 type:create cxid:0x54 zxid:0x81 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12610 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12621 T2042 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> 12622 T2006 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> 12621 T2013 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> 12621 T2026 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> 12644 T2043 oasc.ZkController.register We are http://127.0.0.1:39192/collection1/ and leader is http://127.0.0.1:39192/collection1/
[junit4:junit4]   2> 12645 T2043 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:39192
[junit4:junit4]   2> 12645 T2043 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 12646 T2043 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 12646 T2043 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 12649 T2043 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 12650 T1984 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 12652 T1984 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 12653 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 12723 T1984 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 12725 T1984 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54198
[junit4:junit4]   2> 12726 T1984 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 12727 T1984 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 12727 T1984 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-1363887891482
[junit4:junit4]   2> 12727 T1984 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1363887891482/solr.xml
[junit4:junit4]   2> 12728 T1984 oasc.CoreContainer.<init> New CoreContainer 31545814
[junit4:junit4]   2> 12728 T1984 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-1363887891482/'
[junit4:junit4]   2> 12728 T1984 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-1363887891482/'
[junit4:junit4]   2> 12745 T1984 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 12745 T1984 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 12746 T1984 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 12746 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 12746 T1984 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 12747 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 12747 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 12747 T1984 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 12748 T1984 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 12748 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 12755 T1984 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 12779 T1984 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:50428/solr
[junit4:junit4]   2> 12780 T1984 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 12780 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@32081
[junit4:junit4]   2> 12781 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12781 T2055 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12782 T2055 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 12782 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54179
[junit4:junit4]   2> 12782 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54179
[junit4:junit4]   2> 12783 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac0009 with negotiated timeout 20000 for client /127.0.0.1:54179
[junit4:junit4]   2> 12783 T2055 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac0009, negotiated timeout = 20000
[junit4:junit4]   2> 12783 T2056 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32081 name:ZooKeeperConnection Watcher:127.0.0.1:50428 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12784 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12785 T1989 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8e0d72ac0009
[junit4:junit4]   2> 12786 T2056 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 12786 T1986 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54179 which had sessionid 0x13d8e0d72ac0009
[junit4:junit4]   2> 12786 T1984 oaz.ZooKeeper.close Session: 0x13d8e0d72ac0009 closed
[junit4:junit4]   2> 12786 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 12791 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@1e91f77
[junit4:junit4]   2> 12793 T2057 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 12792 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 12793 T2057 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 12793 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54180
[junit4:junit4]   2> 12794 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54180
[junit4:junit4]   2> 12795 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac000a with negotiated timeout 20000 for client /127.0.0.1:54180
[junit4:junit4]   2> 12795 T2057 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac000a, negotiated timeout = 20000
[junit4:junit4]   2> 12796 T2058 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e91f77 name:ZooKeeperConnection Watcher:127.0.0.1:50428/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 12796 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 12798 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac000a type:create cxid:0x1 zxid:0x8e txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12800 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac000a type:create cxid:0x3 zxid:0x8f txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 12804 T1984 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 13808 T1984 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54198_
[junit4:junit4]   2> 13809 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac000a type:delete cxid:0xd zxid:0x90 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:54198_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:54198_
[junit4:junit4]   2> 13810 T1984 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54198_
[junit4:junit4]   2> 13814 T2013 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> 13814 T2006 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> 13816 T2042 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13817 T2042 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> 13815 T2026 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13816 T2058 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13818 T2026 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> 13820 T2013 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13820 T2006 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 13830 T2059 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-1363887891482/collection1
[junit4:junit4]   2> 13830 T2059 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 13832 T2059 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 13832 T2059 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 13834 T2059 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-1363887891482/collection1/'
[junit4:junit4]   2> 13835 T2059 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-1363887891482/collection1/lib/README' to classloader
[junit4:junit4]   2> 13836 T2059 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-1363887891482/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 13879 T2059 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 13932 T2059 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 13933 T2059 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 13941 T2059 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 14129 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 14130 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"3",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:39192",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:39192_"}
[junit4:junit4]   2> 14133 T2013 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> 14133 T2042 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> 14133 T2058 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> 14133 T2006 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> 14133 T2026 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> 14415 T2059 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 14421 T2059 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 14423 T2059 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 14439 T2059 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14442 T2059 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 14446 T2059 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14447 T2059 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14447 T2059 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14448 T2059 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 14449 T2059 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 14449 T2059 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 14449 T2059 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14450 T2059 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-1363887891482/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty3/
[junit4:junit4]   2> 14450 T2059 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@ff6818
[junit4:junit4]   2> 14450 T2059 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 14451 T2059 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty3 forceNew: false
[junit4:junit4]   2> 14451 T2059 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty3/index/
[junit4:junit4]   2> 14451 T2059 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 14451 T2059 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty3/index forceNew: false
[junit4:junit4]   2> 14452 T2059 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1192b81 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c206b4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 14453 T2059 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 14455 T2059 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 14456 T2059 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 14457 T2059 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 14458 T2059 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 14459 T2059 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 14459 T2059 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 14459 T2059 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 14460 T2059 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 14461 T2059 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 14465 T2059 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 14469 T2059 oass.SolrIndexSearcher.<init> Opening Searcher@d63fa7 main
[junit4:junit4]   2> 14470 T2059 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty3/tlog
[junit4:junit4]   2> 14471 T2059 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 14471 T2059 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 14478 T2060 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d63fa7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 14481 T2059 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 14482 T2059 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 15639 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 15641 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54198",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54198_"}
[junit4:junit4]   2> 15641 T2007 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 15641 T2007 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4:junit4]   2> 15656 T2026 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> 15657 T2006 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> 15657 T2058 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> 15657 T2042 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> 15657 T2013 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> 16484 T2059 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 16484 T2059 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54198 collection:collection1 shard:shard2
[junit4:junit4]   2> 16489 T2059 oasc.ZkController.register We are http://127.0.0.1:54198/collection1/ and leader is http://127.0.0.1:48206/collection1/
[junit4:junit4]   2> 16490 T2059 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54198
[junit4:junit4]   2> 16490 T2059 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 16490 T2059 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C368 name=collection1 org.apache.solr.core.SolrCore@109c457 url=http://127.0.0.1:54198/collection1 node=127.0.0.1:54198_ C368_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, state=down, base_url=http://127.0.0.1:54198, node_name=127.0.0.1:54198_}
[junit4:junit4]   2> 16491 T2061 C368 P54198 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 16492 T2061 C368 P54198 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 16492 T2059 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 16492 T2061 C368 P54198 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 16493 T2061 C368 P54198 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 16494 T1984 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 16495 T2061 C368 P54198 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16495 T1984 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 16496 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 16575 T1984 oejs.Server.doStart jetty-8.1.8.v20121106
[junit4:junit4]   2> 16577 T1984 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56548
[junit4:junit4]   2> 16578 T1984 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4]   2> 16578 T1984 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4]   2> 16578 T1984 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-jetty4-1363887895324
[junit4:junit4]   2> 16579 T1984 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363887895324/solr.xml
[junit4:junit4]   2> 16579 T1984 oasc.CoreContainer.<init> New CoreContainer 19310162
[junit4:junit4]   2> 16579 T1984 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-jetty4-1363887895324/'
[junit4:junit4]   2> 16580 T1984 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-jetty4-1363887895324/'
[junit4:junit4]   2> 16596 T1984 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4]   2> 16597 T1984 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4]   2> 16597 T1984 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4]   2> 16597 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4]   2> 16598 T1984 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4]   2> 16598 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4]   2> 16598 T1984 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4]   2> 16599 T1984 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4]   2> 16599 T1984 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4]   2> 16599 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4]   2> 16605 T1984 oasc.CoreContainer.load Registering Log Listener
[junit4:junit4]   2> 16634 T1984 oasc.CoreContainer.initZooKeeper Zookeeper client=127.0.0.1:50428/solr
[junit4:junit4]   2> 16635 T1984 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4]   2> 16635 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428 sessionTimeout=60000 watcher=org.apache.solr.common.cloud.ConnectionManager@84c819
[junit4:junit4]   2> 16637 T2072 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16637 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16638 T2072 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 16638 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54284
[junit4:junit4]   2> 16638 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54284
[junit4:junit4]   2> 16639 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac000b with negotiated timeout 20000 for client /127.0.0.1:54284
[junit4:junit4]   2> 16639 T2072 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac000b, negotiated timeout = 20000
[junit4:junit4]   2> 16640 T2073 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@84c819 name:ZooKeeperConnection Watcher:127.0.0.1:50428 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16640 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16643 T1989 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8e0d72ac000b
[junit4:junit4]   2> 16644 T2073 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 16644 T1986 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54284 which had sessionid 0x13d8e0d72ac000b
[junit4:junit4]   2> 16644 T1984 oaz.ZooKeeper.close Session: 0x13d8e0d72ac000b closed
[junit4:junit4]   2> 16644 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4]   2> 16648 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428/solr sessionTimeout=30000 watcher=org.apache.solr.common.cloud.ConnectionManager@48c320
[junit4:junit4]   2> 16650 T2074 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 16649 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 16650 T2074 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 16650 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54285
[junit4:junit4]   2> 16651 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54285
[junit4:junit4]   2> 16652 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac000c with negotiated timeout 20000 for client /127.0.0.1:54285
[junit4:junit4]   2> 16652 T2074 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac000c, negotiated timeout = 20000
[junit4:junit4]   2> 16652 T2075 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@48c320 name:ZooKeeperConnection Watcher:127.0.0.1:50428/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 16653 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 16654 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac000c type:create cxid:0x1 zxid:0xa1 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16656 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac000c type:create cxid:0x3 zxid:0xa2 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 16659 T1984 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper... 
[junit4:junit4]   2> 17167 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 17168 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54198",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54198_"}
[junit4:junit4]   2> 17174 T2058 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> 17174 T2006 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> 17174 T2013 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> 17174 T2075 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> 17174 T2042 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> 17174 T2026 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> 17507 T2019 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {version=2&action=PREPRECOVERY&nodeName=127.0.0.1:54198_&core=collection1&wt=javabin&state=recovering&checkLive=true&onlyIfLeader=true&coreNodeName=4} status=0 QTime=1001 
[junit4:junit4]   2> 17662 T1984 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56548_
[junit4:junit4]   2> 17664 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac000c type:delete cxid:0xf zxid:0xa7 txntype:-1 reqpath:n/a Error Path:/solr/live_nodes/127.0.0.1:56548_ Error:KeeperErrorCode = NoNode for /solr/live_nodes/127.0.0.1:56548_
[junit4:junit4]   2> 17666 T1984 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56548_
[junit4:junit4]   2> 17669 T2075 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> 17669 T2026 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> 17669 T2058 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> 17671 T2013 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17671 T2006 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17671 T2042 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17671 T2013 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 17672 T2006 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 17673 T2058 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17673 T2075 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17672 T2042 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 17674 T2026 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4]   2> 17683 T2076 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-jetty4-1363887895324/collection1
[junit4:junit4]   2> 17683 T2076 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4]   2> 17684 T2076 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4]   2> 17685 T2076 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4]   2> 17687 T2076 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-jetty4-1363887895324/collection1/'
[junit4:junit4]   2> 17687 T2076 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363887895324/collection1/lib/README' to classloader
[junit4:junit4]   2> 17688 T2076 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1363887895324/collection1/lib/classes/' to classloader
[junit4:junit4]   2> 17724 T2076 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 17774 T2076 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 17776 T2076 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2> 17783 T2076 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> 18281 T2076 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 18286 T2076 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 18289 T2076 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 18304 T2076 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 18307 T2076 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 18310 T2076 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 18312 T2076 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 18312 T2076 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 18313 T2076 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 18314 T2076 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 18314 T2076 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 18314 T2076 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 18315 T2076 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-jetty4-1363887895324/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty4/
[junit4:junit4]   2> 18315 T2076 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@ff6818
[junit4:junit4]   2> 18315 T2076 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 18316 T2076 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty4 forceNew: false
[junit4:junit4]   2> 18316 T2076 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty4/index/
[junit4:junit4]   2> 18316 T2076 oasc.SolrCore.initIndex WARNING [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 18316 T2076 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty4/index forceNew: false
[junit4:junit4]   2> 18318 T2076 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@aa7cda lockFactory=org.apache.lucene.store.NativeFSLockFactory@18f1be8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 18319 T2076 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 18321 T2076 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 18321 T2076 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 18322 T2076 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 18323 T2076 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 18324 T2076 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 18325 T2076 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 18325 T2076 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 18327 T2076 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 18327 T2076 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 18332 T2076 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 18335 T2076 oass.SolrIndexSearcher.<init> Opening Searcher@1887f9a main
[junit4:junit4]   2> 18336 T2076 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty4/tlog
[junit4:junit4]   2> 18336 T2076 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 18336 T2076 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 18342 T2077 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1887f9a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 18345 T2076 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 18345 T2076 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 18684 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 18685 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:56548",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:56548_"}
[junit4:junit4]   2> 18685 T2007 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4]   2> 18686 T2007 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 18691 T2075 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18692 T2013 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18691 T2006 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18692 T2058 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18691 T2026 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 18692 T2042 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 19347 T2076 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4]   2> 19348 T2076 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56548 collection:collection1 shard:shard1
[junit4:junit4]   2> 19354 T2076 oasc.ZkController.register We are http://127.0.0.1:56548/collection1/ and leader is http://127.0.0.1:39192/collection1/
[junit4:junit4]   2> 19354 T2076 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56548
[junit4:junit4]   2> 19355 T2076 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4]   2> 19355 T2076 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4]   2> ASYNC  NEW_CORE C369 name=collection1 org.apache.solr.core.SolrCore@7adc16 url=http://127.0.0.1:56548/collection1 node=127.0.0.1:56548_ C369_STATE=coll:collection1 core:collection1 props:{core=collection1, collection=collection1, state=down, base_url=http://127.0.0.1:56548, node_name=127.0.0.1:56548_}
[junit4:junit4]   2> 19356 T2078 C369 P56548 oasc.RecoveryStrategy.run Starting recovery process.  core=collection1 recoveringAfterStartup=true
[junit4:junit4]   2> 19361 T2078 C369 P56548 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4]   2> 19362 T2076 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19362 T2078 C369 P56548 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4]   2> 19362 T2078 C369 P56548 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19364 T1984 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1
[junit4:junit4]   2> 19364 T2078 C369 P56548 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19365 T1984 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4]   2> 19366 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19372 T1984 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 19374 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19381 T2020 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-1363887882378/onenodecollectioncore
[junit4:junit4]   2> 19381 T2020 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4]   2> 19383 T2020 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4]   2> 19383 T2020 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4]   2> 19385 T2020 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4]   2> 19386 T2020 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4]   2> 19390 T2020 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4]   2> 19392 T2020 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-1363887882378/onenodecollectioncore/'
[junit4:junit4]   2> 19440 T2020 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4]   2> 19505 T2020 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4]   2> 19506 T2020 oass.IndexSchema.readSchema Reading Solr Schema
[junit4:junit4]   2>  C368_STATE=coll:collection1 core:collection1 props:{shard=shard2, core=collection1, collection=collection1, state=recovering, base_url=http://127.0.0.1:54198, node_name=127.0.0.1:54198_}
[junit4:junit4]   2> 19508 T2061 C368 P54198 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:48206/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 19508 T2061 C368 P54198 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:54198 START replicas=[http://127.0.0.1:48206/collection1/] nUpdates=100
[junit4:junit4]   2> 19508 T2061 C368 P54198 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 19509 T2061 C368 P54198 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 19509 T2061 C368 P54198 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 19509 T2061 C368 P54198 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 19509 T2061 C368 P54198 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 19509 T2061 C368 P54198 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:48206/collection1/. core=collection1
[junit4:junit4]   2> 19509 T2061 C368 P54198 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 19511 T2020 oass.IndexSchema.readSchema Schema name=test
[junit4:junit4]   2> ASYNC  NEW_CORE C370 name=collection1 org.apache.solr.core.SolrCore@13759de url=http://127.0.0.1:48206/collection1 node=127.0.0.1:48206_ C370_STATE=coll:collection1 core:collection1 props:{shard=shard2, core=collection1, collection=collection1, state=active, base_url=http://127.0.0.1:48206, node_name=127.0.0.1:48206_, leader=true}
[junit4:junit4]   2> 19513 T2021 C370 P48206 REQ /get {version=2&qt=/get&wt=javabin&distrib=false&getVersions=100} status=0 QTime=0 
[junit4:junit4]   2> 19515 T2019 C370 P48206 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 19517 T2019 C370 P48206 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@110c344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1990969),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 19517 T2019 C370 P48206 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 19518 T2019 C370 P48206 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@110c344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1990969),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@110c344 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1990969),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19518 T2019 C370 P48206 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19518 T2019 C370 P48206 oass.SolrIndexSearcher.<init> Opening Searcher@3e5a51 realtime
[junit4:junit4]   2> 19519 T2019 C370 P48206 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 19519 T2019 C370 P48206 /update {version=2&commit_end_point=true&openSearcher=false&wt=javabin&softCommit=false&commit=true&waitSearcher=true} {commit=} 0 4
[junit4:junit4]   2> 19520 T2061 C368 P54198 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19520 T2061 C368 P54198 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 19524 T2021 C370 P48206 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 19524 T2021 C370 P48206 REQ /replication {version=2&command=indexversion&qt=/replication&wt=javabin} status=0 QTime=3 
[junit4:junit4]   2> 19525 T2061 C368 P54198 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 19525 T2061 C368 P54198 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 19525 T2061 C368 P54198 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 19527 T2019 C370 P48206 REQ /replication {generation=2&version=2&command=filelist&qt=/replication&wt=javabin} status=0 QTime=0 
[junit4:junit4]   2> 19527 T2061 C368 P54198 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 19528 T2061 C368 P54198 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty3/index.20130321224458347 forceNew: false
[junit4:junit4]   2> 19528 T2061 C368 P54198 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@12cd159 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a6bf38) fullCopy=false
[junit4:junit4]   2> 19530 T2022 C370 P48206 REQ /replication {checksum=true&generation=2&command=filecontent&qt=/replication&wt=filestream&file=segments_2} status=0 QTime=0 
[junit4:junit4]   2> 19531 T2061 C368 P54198 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 19532 T2061 C368 P54198 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 19532 T2061 C368 P54198 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 19533 T2061 C368 P54198 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1192b81 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c206b4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1192b81 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c206b4),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 19533 T2061 C368 P54198 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 19533 T2061 C368 P54198 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 19534 T2061 C368 P54198 oass.SolrIndexSearcher.<init> Opening Searcher@ad7521 main
[junit4:junit4]   2> 19552 T2060 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ad7521 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 19553 T2061 C368 P54198 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 19553 T2061 C368 P54198 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 19553 T2061 C368 P54198 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 19553 T2061 C368 P54198 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 19555 T2061 C368 P54198 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 19983 T2020 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4]   2> 19988 T2020 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4]   2> 19991 T2020 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4]   2> 20007 T2020 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 20012 T2020 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4]   2> 20019 T2020 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 20022 T2020 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 20023 T2020 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 20023 T2020 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4]   2> 20026 T2020 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Unknown key IMPORTANT NOTE
[junit4:junit4]   2> 20026 T2020 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARNING Expected key, got STRING
[junit4:junit4]   2> 20027 T2020 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 20028 T2020 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-1363887882378/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363887878822/onenodecollection/
[junit4:junit4]   2> 20028 T2020 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@ff6818
[junit4:junit4]   2> 20029 T2020 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4]   2> 20030 T2020 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363887878822/onenodecollection forceNew: false
[junit4:junit4]   2> 20031 T2020 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-1363887878822/onenodecollection/index/
[junit4:junit4]   2> 20031 T2020 oasc.SolrCore.initIndex WARNING [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363887878822/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4]   2> 20032 T2020 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363887878822/onenodecollection/index forceNew: false
[junit4:junit4]   2> 20034 T2020 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@670c18 lockFactory=org.apache.lucene.store.NativeFSLockFactory@10e58cf),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 20035 T2020 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 20038 T2020 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4]   2> 20038 T2020 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4]   2> 20039 T2020 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4]   2> 20055 T2020 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4]   2> 20056 T2020 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4]   2> 20057 T2020 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4]   2> 20057 T2020 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4]   2> 20058 T2020 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4]   2> 20059 T2020 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4]   2> 20064 T2020 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4]   2> 20069 T2020 oass.SolrIndexSearcher.<init> Opening Searcher@1a7b78 main
[junit4:junit4]   2> 20070 T2020 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363887878822/onenodecollection/tlog
[junit4:junit4]   2> 20071 T2020 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4]   2> 20072 T2020 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4]   2> 20077 T2082 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@1a7b78 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4]   2> 20079 T2020 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 20200 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 20201 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"recovering",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:56548",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:56548_"}
[junit4:junit4]   2> 20208 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"4",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:54198",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:54198_"}
[junit4:junit4]   2> 20214 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard":null,
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "core_node_name":null,
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48206",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48206_"}
[junit4:junit4]   2> 20214 T2007 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4]   2> 20214 T2007 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4]   2> 20219 T2006 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20220 T2013 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20220 T2075 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20220 T2042 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20220 T2026 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20219 T2058 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 20372 T2036 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {version=2&action=PREPRECOVERY&nodeName=127.0.0.1:56548_&core=collection1&wt=javabin&state=recovering&checkLive=true&onlyIfLeader=true&coreNodeName=5} status=0 QTime=1000 
[junit4:junit4]   2> 21082 T2020 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4]   2> 21083 T2020 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:48206 collection:onenodecollection shard:shard1
[junit4:junit4]   2> 21085 T2020 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4]   2> 21095 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:delete cxid:0xac zxid:0xc2 txntype:-1 reqpath:n/a Error Path:/solr/collections/onenodecollection/leaders Error:KeeperErrorCode = NoNode for /solr/collections/onenodecollection/leaders
[junit4:junit4]   2> 21096 T2020 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4]   2> 21097 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:create cxid:0xad zxid:0xc3 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 21101 T2020 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4]   2> 21101 T2020 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4]   2> 21102 T2020 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:48206/onenodecollectioncore/
[junit4:junit4]   2> 21102 T2020 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4]   2> 21103 T2020 oasc.SyncStrategy.syncToMe http://127.0.0.1:48206/onenodecollectioncore/ has no replicas
[junit4:junit4]   2> 21104 T2020 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:48206/onenodecollectioncore/
[junit4:junit4]   2> 21104 T2020 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4]   2> 21112 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:create cxid:0xb8 zxid:0xc7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 21732 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21745 T2075 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21746 T2058 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21746 T2026 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21746 T2013 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21746 T2042 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21746 T2006 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 21768 T2020 oasc.ZkController.register We are http://127.0.0.1:48206/onenodecollectioncore/ and leader is http://127.0.0.1:48206/onenodecollectioncore/
[junit4:junit4]   2> 21768 T2020 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:48206
[junit4:junit4]   2> 21769 T2020 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4]   2> 21770 T2020 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4]   2> 21772 T2020 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 21774 T2020 oass.SolrDispatchFilter.handleAdminRequest /admin/cores {version=2&action=CREATE&numShards=1&wt=javabin&collection=onenodecollection&dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363887878822/onenodecollection&name=onenodecollectioncore&roles=none} status=0 QTime=2394 
[junit4:junit4]   2> 21775 T1984 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4]   2> 21776 T1984 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2>  C369_STATE=coll:collection1 core:collection1 props:{shard=shard1, core=collection1, collection=collection1, state=recovering, base_url=http://127.0.0.1:56548, node_name=127.0.0.1:56548_}
[junit4:junit4]   2> 22374 T2078 C369 P56548 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:39192/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4]   2> 22374 T2078 C369 P56548 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56548 START replicas=[http://127.0.0.1:39192/collection1/] nUpdates=100
[junit4:junit4]   2> 22375 T2078 C369 P56548 oasu.PeerSync.sync WARNING no frame of reference to tell of we've missed updates
[junit4:junit4]   2> 22375 T2078 C369 P56548 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4]   2> 22375 T2078 C369 P56548 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4]   2> 22376 T2078 C369 P56548 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4]   2> 22376 T2078 C369 P56548 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4]   2> 22377 T2078 C369 P56548 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:39192/collection1/. core=collection1
[junit4:junit4]   2> 22377 T2078 C369 P56548 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> ASYNC  NEW_CORE C371 name=collection1 org.apache.solr.core.SolrCore@a65b86 url=http://127.0.0.1:39192/collection1 node=127.0.0.1:39192_ C371_STATE=coll:collection1 core:collection1 props:{shard=shard1, core=collection1, collection=collection1, state=active, base_url=http://127.0.0.1:39192, node_name=127.0.0.1:39192_, leader=true}
[junit4:junit4]   2> 22383 T2035 C371 P39192 REQ /get {version=2&qt=/get&wt=javabin&distrib=false&getVersions=100} status=0 QTime=0 
[junit4:junit4]   2> 22384 T2037 C371 P39192 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4]   2> 22387 T2037 C371 P39192 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=1
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@16382c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1285fd4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 22388 T2037 C371 P39192 oasc.SolrDeletionPolicy.updateCommits newest commit = 1[segments_1]
[junit4:junit4]   2> 22390 T2037 C371 P39192 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@16382c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1285fd4),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@16382c2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1285fd4),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 22390 T2037 C371 P39192 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 22391 T2037 C371 P39192 oass.SolrIndexSearcher.<init> Opening Searcher@1f87064 realtime
[junit4:junit4]   2> 22392 T2037 C371 P39192 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4]   2> 22392 T2037 C371 P39192 /update {version=2&commit_end_point=true&openSearcher=false&wt=javabin&softCommit=false&commit=true&waitSearcher=true} {commit=} 0 8
[junit4:junit4]   2> 22393 T2078 C369 P56548 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 22394 T2078 C369 P56548 oash.SnapPuller.<init>  No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4]   2> 22396 T2036 C371 P39192 oash.ReplicationHandler.inform Commits will be reserved for  10000
[junit4:junit4]   2> 22396 T2036 C371 P39192 REQ /replication {version=2&command=indexversion&qt=/replication&wt=javabin} status=0 QTime=1 
[junit4:junit4]   2> 22397 T2078 C369 P56548 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4]   2> 22398 T2078 C369 P56548 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4]   2> 22398 T2078 C369 P56548 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4]   2> 22400 T2035 C371 P39192 REQ /replication {generation=2&version=2&command=filelist&qt=/replication&wt=javabin} status=0 QTime=0 
[junit4:junit4]   2> 22401 T2078 C369 P56548 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4]   2> 22402 T2078 C369 P56548 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty4/index.20130321224501220 forceNew: false
[junit4:junit4]   2> 22403 T2078 C369 P56548 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@eb0948 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b07d8a) fullCopy=false
[junit4:junit4]   2> 22405 T2037 C371 P39192 REQ /replication {checksum=true&generation=2&command=filecontent&qt=/replication&wt=filestream&file=segments_2} status=0 QTime=0 
[junit4:junit4]   2> 22407 T2078 C369 P56548 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4]   2> 22408 T2078 C369 P56548 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4]   2> 22409 T2078 C369 P56548 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4]   2> 22410 T2078 C369 P56548 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits:num=2
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@aa7cda lockFactory=org.apache.lucene.store.NativeFSLockFactory@18f1be8),segFN=segments_1,generation=1,filenames=[segments_1]
[junit4:junit4]   2> 		commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@aa7cda lockFactory=org.apache.lucene.store.NativeFSLockFactory@18f1be8),segFN=segments_2,generation=2,filenames=[segments_2]
[junit4:junit4]   2> 22410 T2078 C369 P56548 oasc.SolrDeletionPolicy.updateCommits newest commit = 2[segments_2]
[junit4:junit4]   2> 22411 T2078 C369 P56548 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4]   2> 22411 T2078 C369 P56548 oass.SolrIndexSearcher.<init> Opening Searcher@8b13c2 main
[junit4:junit4]   2> 22413 T2077 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8b13c2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4]   2> 22413 T2078 C369 P56548 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4]   2> 22414 T2078 C369 P56548 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4]   2> 22414 T2078 C369 P56548 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4]   2> 22414 T2078 C369 P56548 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 22416 T2078 C369 P56548 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4]   2> 22779 T1984 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23256 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23257 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"1",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:48206__onenodecollectioncore",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48206",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48206_"}
[junit4:junit4]   2> 23263 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"5",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"active",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:56548",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:56548_"}
[junit4:junit4]   2> 23269 T2075 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23269 T2006 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23269 T2058 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23269 T2013 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23269 T2026 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23269 T2042 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 23782 T1984 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 23784 T1984 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4]   2> 23785 T1984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4]   2> 23803 T1984 oaz.ZooKeeper.<init> Initiating client connection, connectString=127.0.0.1:50428 sessionTimeout=10000 watcher=org.apache.solr.common.cloud.ConnectionManager@1512d8
[junit4:junit4]   2> 23805 T2085 oaz.ClientCnxn$SendThread.logStartConnect Opening socket connection to server localhost.localdomain/127.0.0.1:50428. Will not attempt to authenticate using SASL (access denied ("javax.security.auth.AuthPermission" "getLoginConfiguration"))
[junit4:junit4]   2> 23805 T1984 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4]   2> 23806 T2085 oaz.ClientCnxn$SendThread.primeConnection Socket connection established to localhost.localdomain/127.0.0.1:50428, initiating session
[junit4:junit4]   2> 23807 T1986 oazs.NIOServerCnxnFactory.run Accepted socket connection from /127.0.0.1:54478
[junit4:junit4]   2> 23807 T1986 oazs.ZooKeeperServer.processConnectRequest Client attempting to establish new session at /127.0.0.1:54478
[junit4:junit4]   2> 23809 T1988 oazs.ZooKeeperServer.finishSessionInit Established session 0x13d8e0d72ac000d with negotiated timeout 10000 for client /127.0.0.1:54478
[junit4:junit4]   2> 23809 T2085 oaz.ClientCnxn$SendThread.onConnected Session establishment complete on server localhost.localdomain/127.0.0.1:50428, sessionid = 0x13d8e0d72ac000d, negotiated timeout = 10000
[junit4:junit4]   2> 23810 T2086 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1512d8 name:ZooKeeperConnection Watcher:127.0.0.1:50428 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4]   2> 23810 T1984 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4]   2> 23888 T1989 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8e0d72ac000d
[junit4:junit4]   2> 23889 T2086 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23889 T1986 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54478 which had sessionid 0x13d8e0d72ac000d
[junit4:junit4]   2> 23889 T1984 oaz.ZooKeeper.close Session: 0x13d8e0d72ac000d closed
[junit4:junit4]   2> 23891 T1989 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8e0d72ac0004
[junit4:junit4]   2> 23891 T1986 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54155 which had sessionid 0x13d8e0d72ac0004
[junit4:junit4]   2> 23891 T1984 oaz.ZooKeeper.close Session: 0x13d8e0d72ac0004 closed
[junit4:junit4]   2> 23892 T2013 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 23896 T1984 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 46693
[junit4:junit4]   2> 23897 T1984 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=11214518
[junit4:junit4]   2> 24778 T2007 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 24780 T2007 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:46693",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:46693_"}
[junit4:junit4]   2> 24786 T2006 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 24786 T2075 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 24787 T2026 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 24786 T2042 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 24786 T2058 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 25899 T1984 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 25900 T1984 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 25905 T1984 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@168b480
[junit4:junit4]   2> 25912 T1984 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> 25913 T1984 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 25913 T1984 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 25914 T1984 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 25915 T1984 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 25917 T1984 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/control/data
[junit4:junit4]   2> 25917 T1984 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/control/data
[junit4:junit4]   2> 25918 T1984 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/control/data/index
[junit4:junit4]   2> 25919 T1984 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/control/data/index
[junit4:junit4]   2> 25921 T2007 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89383756026871811-127.0.0.1:46693_-n_0000000000) am no longer a leader.
[junit4:junit4]   2> 25921 T1989 oazs.PrepRequestProcessor.pRequest2Txn Processed session termination for sessionid: 0x13d8e0d72ac0003
[junit4:junit4]   2> 25923 T2006 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 25923 T2058 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4]   2> 25923 T1984 oaz.ZooKeeper.close Session: 0x13d8e0d72ac0003 closed
[junit4:junit4]   2> 25923 T1986 oazs.NIOServerCnxn.closeSock Closed socket connection for client /127.0.0.1:54154 which had sessionid 0x13d8e0d72ac0003
[junit4:junit4]   2> 25923 T2006 oascc.ZkStateReader$2.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 25925 T2006 oascc.ZkStateReader$3.process WARNING ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4]   2> 25925 T2075 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25926 T2075 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> 25925 T2042 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25925 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:delete cxid:0xc6 zxid:0xe3 txntype:-1 reqpath:n/a Error Path:/solr/overseer_elect/leader Error:KeeperErrorCode = NoNode for /solr/overseer_elect/leader
[junit4:junit4]   2> 25926 T2042 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> 25925 T2006 oaz.ClientCnxn$EventThread.run EventThread shut down
[junit4:junit4]   2> 25928 T2026 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4]   2> 25929 T2058 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25932 T2026 oasc.Overseer.start Overseer (id=89383756026871814-127.0.0.1:48206_-n_0000000001) starting
[junit4:junit4]   2> 25932 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:create cxid:0xcb zxid:0xe5 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25934 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:create cxid:0xcc zxid:0xe6 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25937 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:create cxid:0xce zxid:0xe7 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25939 T1989 oazs.PrepRequestProcessor.pRequest Got user-level KeeperException when processing sessionid:0x13d8e0d72ac0006 type:create cxid:0xd0 zxid:0xe8 txntype:-1 reqpath:n/a Error Path:/solr/overseer Error:KeeperErrorCode = NodeExists for /solr/overseer
[junit4:junit4]   2> 25941 T2088 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4]   2> 25942 T2026 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4]   2> 25942 T2026 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> 25943 T2087 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4]   2> 25947 T2087 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 25947 T1984 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4]   2> 25948 T2087 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "numShards":"2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"1",
[junit4:junit4]   2> 	  "collection":"control_collection",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:46693",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:46693_"}
[junit4:junit4]   2> 25952 T2075 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> 25952 T2042 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> 25952 T2026 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> 25952 T2058 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> 25999 T1984 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 48206
[junit4:junit4]   2> 26000 T1984 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=2787364
[junit4:junit4]   2> 27459 T2087 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper... 
[junit4:junit4]   2> 27460 T2087 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "shard":"shard1",
[junit4:junit4]   2> 	  "core":"onenodecollectioncore",
[junit4:junit4]   2> 	  "core_node_name":"127.0.0.1:48206__onenodecollectioncore",
[junit4:junit4]   2> 	  "collection":"onenodecollection",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":"none",
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48206",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48206_"}
[junit4:junit4]   2> 27466 T2087 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4]   2> 	  "shard":"shard2",
[junit4:junit4]   2> 	  "core":"collection1",
[junit4:junit4]   2> 	  "core_node_name":"2",
[junit4:junit4]   2> 	  "collection":"collection1",
[junit4:junit4]   2> 	  "state":"down",
[junit4:junit4]   2> 	  "operation":"state",
[junit4:junit4]   2> 	  "roles":null,
[junit4:junit4]   2> 	  "base_url":"http://127.0.0.1:48206",
[junit4:junit4]   2> 	  "node_name":"127.0.0.1:48206_"}
[junit4:junit4]   2> 27470 T2026 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> 27470 T2058 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> 27470 T2075 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> 27470 T2042 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> 29004 T1984 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4]   2> 29005 T1984 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4]   2> 29008 T1984 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4]   2> 29012 T1984 oasc.SolrCore.close [collection1]  CLOSING SolrCore org.apache.solr.core.SolrCore@13759de
[junit4:junit4]   2> 29019 T1984 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> 29020 T1984 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 29021 T1984 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 29021 T1984 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 29023 T1984 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4]   2> 29024 T1984 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty1
[junit4:junit4]   2> 29024 T1984 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty1
[junit4:junit4]   2> 29025 T1984 oasc.CachingDirectoryFactory.close Closing directory when closing factory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty1/index
[junit4:junit4]   2> 29026 T1984 oasc.CachingDirectoryFactory.closeDirectory Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1363887878822/jetty1/index
[junit4:junit4]   2> 29026 T1984 oasc.SolrCore.close [onenodecollectioncore]  CLOSING SolrCore org.apache.solr.core.SolrCore@1e90f60
[junit4:junit4]   2> 29036 T1984 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> 29037 T1984 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4]   2> 29037 T1984 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4]   2> 29038 T1984 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4]   2> 29039 T1984 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4]   2> 29040 T1984 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363887878822/onenodecollection
[junit4:junit4]   2> 29041 T1984 oasc.CachingDirectoryFactory.closeDirectory Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363887878822/onenodecollection
[junit4:junit4]   2> 29042 T1984 oasc.CachingDirectoryFactory.close Closing directory when closing factory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J1/./solrtest-BasicDistributedZk2Test-1363887878822/onenodecollection/index
[junit4:junit4]   2> 29042 T1984 oasc.Cachin

[...truncated too long message...]

  1>        {"id":"89383758252277763-127.0.0.1:57176_ohz%2Fk-n_0000000000"}
[junit4:junit4]   1>  /zookeeper (1)
[junit4:junit4]   1>  DATA:
[junit4:junit4]   1>      
[junit4:junit4]   1> 
[junit4:junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=UnloadDistributedZkTest -Dtests.method=testDistribSearch -Dtests.seed=87929F081E7A37E7 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=nl_NL -Dtests.timezone=Asia/Tbilisi -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE  139s J1 | UnloadDistributedZkTest.testDistribSearch <<<
[junit4:junit4]    > Throwable #1: java.lang.AssertionError: Still found shard2 in collection test_unload_shard_and_collection
[junit4:junit4]    > 	at __randomizedtesting.SeedInfo.seed([87929F081E7A37E7:6741110692557DB]:0)
[junit4:junit4]    > 	at org.junit.Assert.fail(Assert.java:93)
[junit4:junit4]    > 	at org.apache.solr.cloud.UnloadDistributedZkTest.testUnloadShardAndCollection(UnloadDistributedZkTest.java:124)
[junit4:junit4]    > 	at org.apache.solr.cloud.UnloadDistributedZkTest.doTest(UnloadDistributedZkTest.java:77)
[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:57)
[junit4:junit4]    > 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4:junit4]    > 	at java.lang.reflect.Method.invoke(Method.java:487)
[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:722)
[junit4:junit4]   2> 139393 T2097 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4]   2> 139402 T2096 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4]   2> 140224 T2100 oazs.SessionTrackerImpl.run SessionTrackerImpl exited loop!
[junit4:junit4]   2> NOTE: test params are: codec=Lucene42: {a_t=MockVariableIntBlock(baseBlockSize=33), a_si=PostingsFormat(name=Direct), text=PostingsFormat(name=MockRandom), range_facet_sl=PostingsFormat(name=Memory doPackFST= false), range_facet_si=MockVariableIntBlock(baseBlockSize=33), range_facet_l=MockVariableIntBlock(baseBlockSize=33), other_tl1=PostingsFormat(name=Direct), id=PostingsFormat(name=Memory doPackFST= false), _version_=PostingsFormat(name=Direct), intDefault=PostingsFormat(name=Direct), multiDefault=MockVariableIntBlock(baseBlockSize=33), timestamp=MockVariableIntBlock(baseBlockSize=33)}, docValues:{timestamp=DocValuesFormat(name=Asserting)}, sim=DefaultSimilarity, locale=nl_NL, timezone=Asia/Tbilisi
[junit4:junit4]   2> NOTE: Linux 3.2.0-39-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=2,free=74078272,total=147509248
[junit4:junit4]   2> NOTE: All tests run in this JVM: [XsltUpdateRequestHandlerTest, NotRequiredUniqueKeyTest, TestStressReorder, TestAtomicUpdateErrorCases, PingRequestHandlerTest, CollectionsAPIDistributedZkTest, SpellPossibilityIteratorTest, SignatureUpdateProcessorFactoryTest, TestRecovery, SolrPluginUtilsTest, TestSolrJ, TestSystemIdResolver, TestStressLucene, TestCSVResponseWriter, DefaultValueUpdateProcessorTest, TestComponentsName, DisMaxRequestHandlerTest, StatsComponentTest, DOMUtilTest, TestSolrDiscoveryProperties, TestZkChroot, TestRandomFaceting, TestFieldCollectionResource, BadIndexSchemaTest, BasicZkTest, DocValuesMultiTest, UniqFieldsUpdateProcessorFactoryTest, TestJmxMonitoredMap, TestRTGBase, SolrCmdDistributorTest, SimplePostToolTest, SpellCheckCollatorTest, TestOmitPositions, CopyFieldTest, TestCSVLoader, TestMultiCoreConfBootstrap, CoreContainerCoreInitFailuresTest, AliasIntegrationTest, ConvertedLegacyTest, HardAutoCommitTest, NumericFieldsTest, TestReload, SuggesterTSTTest, UpdateParamsTest, XmlUpdateRequestHandlerTest, TestNumberUtils, TestJmxIntegration, TestLazyCores, TestQuerySenderNoQuery, TestSuggestSpellingConverter, TestSolr4Spatial, TestSolrXMLSerializer, TestFastOutputStream, IndexReaderFactoryTest, SampleTest, HighlighterTest, TestIndexingPerformance, TestRangeQuery, DirectUpdateHandlerTest, OpenCloseCoreStressTest, SolrRequestParserTest, SuggesterWFSTTest, DistanceFunctionTest, FullSolrCloudDistribCmdsTest, TestDynamicFieldResource, BasicDistributedZk2Test, UnloadDistributedZkTest]
[junit4:junit4] Completed on J1 in 140.45s, 1 test, 1 failure <<< FAILURES!

[...truncated 410 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:375: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:355: 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:1210: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:874: There were test failures: 272 suites, 1144 tests, 1 error, 1 failure, 13 ignored (7 assumptions)

Total time: 47 minutes 33 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Description set: Java: 32bit/jdk1.8.0-ea-b79 -client -XX:+UseSerialGC
Email was triggered for: Failure
Sending email for trigger: Failure



Mime
View raw message