You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/05/26 01:19:19 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/ibm-j9-jdk7) - Build #
5831 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/5831/
Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
2 tests failed.
REGRESSION: org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch
Error Message:
Server at http://127.0.0.1:59841/n_uu/onenodecollectioncore returned non ok status:404, message:Can not find: /n_uu/onenodecollectioncore/update
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:59841/n_uu/onenodecollectioncore returned non ok status:404, message:Can not find: /n_uu/onenodecollectioncore/update
at __randomizedtesting.SeedInfo.seed([E3057B1F8FCF161F:62E3F507F8907623]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
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:198)
at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:90)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:613)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:780)
REGRESSION: org.apache.solr.update.HardAutoCommitTest.testCommitWithin
Error Message:
Exception during query
Stack Trace:
java.lang.RuntimeException: Exception during query
at __randomizedtesting.SeedInfo.seed([E3057B1F8FCF161F:59D714670CE1F80A]:0)
at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:525)
at org.apache.solr.update.HardAutoCommitTest.testCommitWithin(HardAutoCommitTest.java:79)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:613)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:780)
Caused by: java.lang.RuntimeException: REQUEST FAILED: xpath=//result[@numFound=0]
xml response was: <?xml version="1.0" encoding="UTF-8"?>
<response>
<lst name="responseHeader"><int name="status">0</int><int name="QTime">3168</int></lst><result name="response" numFound="1" start="0"><doc><int name="id">529</int><int name="range_facet_si">529</int><arr name="range_facet_l"><long>529</long></arr><arr name="range_facet_sl"><long>529</long></arr><arr name="field_t"><str>what's inside?</str></arr><arr name="subject"><str>info</str></arr><int name="intDefault">42</int><date name="timestamp">2013-05-25T23:13:45.843Z</date><arr name="multiDefault"><str>muLti-Default</str></arr></doc></result>
</response>
request was:q=id:529&start=0&qt=standard&version=2.2&rows=20
at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:518)
... 41 more
Build Log:
[...truncated 9598 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.BasicDistributedZk2Test
[junit4:junit4] 2> 610685 T2393 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /n_uu/
[junit4:junit4] 2> 610689 T2393 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991
[junit4:junit4] 2> 610690 T2393 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 610690 T2394 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 610790 T2393 oasc.ZkTestServer.run start zk server on port:42389
[junit4:junit4] 2> 610792 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 610794 T2400 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@eb71a5e5 name:ZooKeeperConnection Watcher:127.0.0.1:42389 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 610794 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 610794 T2393 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 610797 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 610798 T2402 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d0bc0146 name:ZooKeeperConnection Watcher:127.0.0.1:42389/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 610798 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 610798 T2393 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 610801 T2393 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 610803 T2393 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 610804 T2393 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 610806 T2393 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> 610807 T2393 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 610810 T2393 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> 610811 T2393 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 610813 T2393 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> 610814 T2393 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 610816 T2393 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> 610817 T2393 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 610818 T2393 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> 610819 T2393 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 610821 T2393 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> 610822 T2393 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 610823 T2393 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> 610824 T2393 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 610826 T2393 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> 610827 T2393 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 610829 T2393 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> 610830 T2393 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 610897 T2393 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 610899 T2393 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52302
[junit4:junit4] 2> 610899 T2393 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 610900 T2393 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 610901 T2393 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369523183134
[junit4:junit4] 2> 610901 T2393 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369523183134/solr.xml
[junit4:junit4] 2> 610902 T2393 oasc.CoreContainer.<init> New CoreContainer 58847713
[junit4:junit4] 2> 610903 T2393 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369523183134/'
[junit4:junit4] 2> 610903 T2393 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369523183134/'
[junit4:junit4] 2> 610940 T2393 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 610941 T2393 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 610941 T2393 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 610942 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 610943 T2393 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 610943 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 610944 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 610944 T2393 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 610945 T2393 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 610946 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 610951 T2393 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 610952 T2393 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42389/solr
[junit4:junit4] 2> 610952 T2393 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 610953 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 610955 T2413 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e66f6fb2 name:ZooKeeperConnection Watcher:127.0.0.1:42389 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 610955 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 610956 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 610962 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 610963 T2415 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@50887436 name:ZooKeeperConnection Watcher:127.0.0.1:42389/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 610963 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 610964 T2393 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 610967 T2393 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 610969 T2393 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 610970 T2393 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52302_n_uu
[junit4:junit4] 2> 610972 T2393 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52302_n_uu
[junit4:junit4] 2> 610974 T2393 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 610979 T2393 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 610982 T2393 oasc.Overseer.start Overseer (id=89753071320694787-127.0.0.1:52302_n_uu-n_0000000000) starting
[junit4:junit4] 2> 610985 T2393 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 610991 T2417 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 610992 T2393 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 610995 T2393 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 610997 T2393 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 610999 T2416 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 611001 T2418 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369523183134/collection1
[junit4:junit4] 2> 611002 T2418 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 611002 T2418 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 611002 T2418 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 611003 T2418 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369523183134/collection1/'
[junit4:junit4] 2> 611004 T2418 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369523183134/collection1/lib/README' to classloader
[junit4:junit4] 2> 611004 T2418 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369523183134/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 611027 T2418 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 611068 T2418 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 611070 T2418 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 611074 T2418 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 611387 T2418 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 611392 T2418 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 611395 T2418 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 611404 T2418 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 611407 T2418 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 611411 T2418 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 611412 T2418 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 611412 T2418 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 611412 T2418 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 611413 T2418 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 611414 T2418 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 611414 T2418 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 611414 T2418 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-controljetty-1369523183134/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data/
[junit4:junit4] 2> 611415 T2418 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@fa441e07
[junit4:junit4] 2> 611415 T2418 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 611416 T2418 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data
[junit4:junit4] 2> 611416 T2418 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data/index/
[junit4:junit4] 2> 611417 T2418 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 611417 T2418 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data/index
[junit4:junit4] 2> 611419 T2418 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a64d3279 lockFactory=org.apache.lucene.store.NativeFSLockFactory@dc430063),segFN=segments_1,generation=1}
[junit4:junit4] 2> 611419 T2418 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 611420 T2418 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 611421 T2418 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 611421 T2418 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 611422 T2418 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 611422 T2418 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 611423 T2418 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 611423 T2418 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 611423 T2418 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 611424 T2418 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 611425 T2418 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 611427 T2418 oass.SolrIndexSearcher.<init> Opening Searcher@4dcb3db4 main
[junit4:junit4] 2> 611427 T2418 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data/tlog
[junit4:junit4] 2> 611428 T2418 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 611428 T2418 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 611432 T2419 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4dcb3db4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 611432 T2418 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 611433 T2418 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 612501 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 612502 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52302/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52302_n_uu",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 612502 T2416 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 612503 T2416 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 612505 T2415 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> 613434 T2418 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 613435 T2418 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52302/n_uu collection:control_collection shard:shard1
[junit4:junit4] 2> 613436 T2418 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 613446 T2418 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 613450 T2418 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 613451 T2418 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 613452 T2418 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52302/n_uu/collection1/
[junit4:junit4] 2> 613454 T2418 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 613456 T2418 oasc.SyncStrategy.syncToMe http://127.0.0.1:52302/n_uu/collection1/ has no replicas
[junit4:junit4] 2> 613456 T2418 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52302/n_uu/collection1/
[junit4:junit4] 2> 613457 T2418 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 614009 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 614019 T2415 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> 614063 T2418 oasc.ZkController.register We are http://127.0.0.1:52302/n_uu/collection1/ and leader is http://127.0.0.1:52302/n_uu/collection1/
[junit4:junit4] 2> 614064 T2418 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52302/n_uu
[junit4:junit4] 2> 614064 T2418 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 614064 T2418 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 614065 T2418 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 614066 T2418 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 614067 T2393 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 614068 T2393 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 614068 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 614074 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 614076 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 614077 T2422 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d7672cba name:ZooKeeperConnection Watcher:127.0.0.1:42389/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 614077 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 614079 T2393 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 614080 T2393 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 614155 T2393 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 614157 T2393 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55419
[junit4:junit4] 2> 614158 T2393 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 614159 T2393 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 614159 T2393 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383
[junit4:junit4] 2> 614160 T2393 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/solr.xml
[junit4:junit4] 2> 614161 T2393 oasc.CoreContainer.<init> New CoreContainer 2013579373
[junit4:junit4] 2> 614162 T2393 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/'
[junit4:junit4] 2> 614163 T2393 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/'
[junit4:junit4] 2> 614209 T2393 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 614210 T2393 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 614210 T2393 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 614211 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 614211 T2393 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 614212 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 614213 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 614213 T2393 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 614214 T2393 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 614215 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 614219 T2393 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 614220 T2393 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42389/solr
[junit4:junit4] 2> 614221 T2393 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 614222 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 614223 T2433 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a4d5fd7b name:ZooKeeperConnection Watcher:127.0.0.1:42389 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 614223 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 614225 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 614230 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 614231 T2435 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c9dbcc90 name:ZooKeeperConnection Watcher:127.0.0.1:42389/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 614231 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 614233 T2393 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 615236 T2393 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55419_n_uu
[junit4:junit4] 2> 615237 T2393 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55419_n_uu
[junit4:junit4] 2> 615240 T2422 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 615240 T2415 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 615240 T2435 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 615241 T2415 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> 615256 T2436 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/collection1
[junit4:junit4] 2> 615256 T2436 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 615257 T2436 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 615257 T2436 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 615258 T2436 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/collection1/'
[junit4:junit4] 2> 615259 T2436 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/collection1/lib/README' to classloader
[junit4:junit4] 2> 615259 T2436 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 615283 T2436 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 615313 T2436 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 615314 T2436 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 615318 T2436 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 615523 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 615524 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52302/n_uu",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52302_n_uu",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 615526 T2415 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> 615526 T2435 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> 615526 T2422 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> 615619 T2436 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 615623 T2436 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 615626 T2436 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 615634 T2436 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 615637 T2436 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 615641 T2436 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 615641 T2436 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 615642 T2436 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 615642 T2436 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 615643 T2436 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 615643 T2436 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 615644 T2436 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 615644 T2436 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1/
[junit4:junit4] 2> 615644 T2436 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@fa441e07
[junit4:junit4] 2> 615645 T2436 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 615646 T2436 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1
[junit4:junit4] 2> 615646 T2436 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1/index/
[junit4:junit4] 2> 615646 T2436 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 615647 T2436 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1/index
[junit4:junit4] 2> 615648 T2436 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76c97554 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a058c8fb),segFN=segments_1,generation=1}
[junit4:junit4] 2> 615648 T2436 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 615650 T2436 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 615650 T2436 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 615651 T2436 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 615651 T2436 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 615652 T2436 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 615652 T2436 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 615653 T2436 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 615653 T2436 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 615654 T2436 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 615655 T2436 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 615656 T2436 oass.SolrIndexSearcher.<init> Opening Searcher@edfca7c8 main
[junit4:junit4] 2> 615657 T2436 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1/tlog
[junit4:junit4] 2> 615658 T2436 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 615658 T2436 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 615662 T2437 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@edfca7c8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 615664 T2436 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 615664 T2436 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 617030 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 617031 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55419/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:55419_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 617031 T2416 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 617032 T2416 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 617037 T2415 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> 617037 T2422 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> 617038 T2435 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> 617666 T2436 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 617666 T2436 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55419/n_uu collection:collection1 shard:shard1
[junit4:junit4] 2> 617667 T2436 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 617676 T2436 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 617678 T2436 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 617679 T2436 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 617679 T2436 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55419/n_uu/collection1/
[junit4:junit4] 2> 617679 T2436 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 617680 T2436 oasc.SyncStrategy.syncToMe http://127.0.0.1:55419/n_uu/collection1/ has no replicas
[junit4:junit4] 2> 617680 T2436 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:55419/n_uu/collection1/
[junit4:junit4] 2> 617680 T2436 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 618542 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 618547 T2422 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> 618547 T2415 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> 618547 T2435 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> 618586 T2436 oasc.ZkController.register We are http://127.0.0.1:55419/n_uu/collection1/ and leader is http://127.0.0.1:55419/n_uu/collection1/
[junit4:junit4] 2> 618587 T2436 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55419/n_uu
[junit4:junit4] 2> 618587 T2436 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 618588 T2436 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 618588 T2436 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 618589 T2436 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 618591 T2393 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 618591 T2393 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 618592 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 618661 T2393 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 618662 T2393 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59841
[junit4:junit4] 2> 618663 T2393 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 618664 T2393 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 618664 T2393 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369523190899
[junit4:junit4] 2> 618665 T2393 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369523190899/solr.xml
[junit4:junit4] 2> 618666 T2393 oasc.CoreContainer.<init> New CoreContainer -681137677
[junit4:junit4] 2> 618666 T2393 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369523190899/'
[junit4:junit4] 2> 618667 T2393 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369523190899/'
[junit4:junit4] 2> 618719 T2393 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 618719 T2393 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 618720 T2393 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 618720 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 618721 T2393 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 618722 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 618722 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 618723 T2393 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 618723 T2393 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 618724 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 618729 T2393 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 618730 T2393 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42389/solr
[junit4:junit4] 2> 618731 T2393 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 618732 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 618733 T2449 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b1f62228 name:ZooKeeperConnection Watcher:127.0.0.1:42389 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 618734 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 618735 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 618740 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 618742 T2451 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c3145bc6 name:ZooKeeperConnection Watcher:127.0.0.1:42389/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 618742 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 618745 T2393 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 619748 T2393 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59841_n_uu
[junit4:junit4] 2> 619750 T2393 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59841_n_uu
[junit4:junit4] 2> 619752 T2422 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> 619752 T2451 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 619752 T2415 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 619752 T2435 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> 619753 T2415 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> 619754 T2422 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 619755 T2435 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 619757 T2452 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369523190899/collection1
[junit4:junit4] 2> 619757 T2452 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 619758 T2452 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 619758 T2452 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 619760 T2452 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369523190899/collection1/'
[junit4:junit4] 2> 619760 T2452 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369523190899/collection1/lib/README' to classloader
[junit4:junit4] 2> 619761 T2452 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369523190899/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 619787 T2452 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 619820 T2452 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 619822 T2452 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 619828 T2452 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 620050 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 620051 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55419/n_uu",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:55419_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 620053 T2451 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> 620053 T2415 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> 620053 T2422 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> 620053 T2435 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> 620151 T2452 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 620156 T2452 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 620158 T2452 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 620166 T2452 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 620170 T2452 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 620173 T2452 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 620174 T2452 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 620174 T2452 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 620175 T2452 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 620176 T2452 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 620176 T2452 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 620176 T2452 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 620177 T2452 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty2-1369523190899/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2/
[junit4:junit4] 2> 620177 T2452 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@fa441e07
[junit4:junit4] 2> 620186 T2452 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 620187 T2452 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2
[junit4:junit4] 2> 620188 T2452 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2/index/
[junit4:junit4] 2> 620188 T2452 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 620188 T2452 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2/index
[junit4:junit4] 2> 620190 T2452 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b07666d8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8565c54f),segFN=segments_1,generation=1}
[junit4:junit4] 2> 620190 T2452 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 620192 T2452 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 620192 T2452 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 620192 T2452 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 620193 T2452 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 620194 T2452 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 620194 T2452 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 620194 T2452 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 620195 T2452 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 620195 T2452 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 620196 T2452 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 620198 T2452 oass.SolrIndexSearcher.<init> Opening Searcher@54d36989 main
[junit4:junit4] 2> 620199 T2452 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2/tlog
[junit4:junit4] 2> 620199 T2452 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 620200 T2452 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 620204 T2453 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@54d36989 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 620205 T2452 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 620206 T2452 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 621558 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 621558 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59841/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:59841_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 621559 T2416 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 621559 T2416 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 621563 T2451 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> 621563 T2435 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> 621563 T2415 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> 621563 T2422 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> 622207 T2452 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 622208 T2452 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59841/n_uu collection:collection1 shard:shard2
[junit4:junit4] 2> 622209 T2452 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 622213 T2452 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 622214 T2452 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 622215 T2452 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 622215 T2452 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59841/n_uu/collection1/
[junit4:junit4] 2> 622216 T2452 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 622216 T2452 oasc.SyncStrategy.syncToMe http://127.0.0.1:59841/n_uu/collection1/ has no replicas
[junit4:junit4] 2> 622217 T2452 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59841/n_uu/collection1/
[junit4:junit4] 2> 622217 T2452 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 623066 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 623072 T2451 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> 623072 T2422 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> 623072 T2415 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> 623072 T2435 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> 623122 T2452 oasc.ZkController.register We are http://127.0.0.1:59841/n_uu/collection1/ and leader is http://127.0.0.1:59841/n_uu/collection1/
[junit4:junit4] 2> 623123 T2452 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59841/n_uu
[junit4:junit4] 2> 623123 T2452 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 623124 T2452 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 623124 T2452 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 623126 T2452 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 623127 T2393 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 623128 T2393 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 623128 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 623201 T2393 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 623203 T2393 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:60699
[junit4:junit4] 2> 623204 T2393 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 623205 T2393 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 623205 T2393 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369523195435
[junit4:junit4] 2> 623206 T2393 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369523195435/solr.xml
[junit4:junit4] 2> 623206 T2393 oasc.CoreContainer.<init> New CoreContainer -489540076
[junit4:junit4] 2> 623207 T2393 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369523195435/'
[junit4:junit4] 2> 623208 T2393 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369523195435/'
[junit4:junit4] 2> 623248 T2393 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 623249 T2393 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 623250 T2393 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 623250 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 623251 T2393 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 623252 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 623252 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 623253 T2393 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 623254 T2393 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 623254 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 623260 T2393 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 623261 T2393 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42389/solr
[junit4:junit4] 2> 623262 T2393 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 623263 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 623264 T2465 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b0a3a7ac name:ZooKeeperConnection Watcher:127.0.0.1:42389 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 623265 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 623266 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 623271 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 623273 T2467 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a9dd32f9 name:ZooKeeperConnection Watcher:127.0.0.1:42389/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 623273 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 623276 T2393 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 624278 T2393 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60699_n_uu
[junit4:junit4] 2> 624280 T2393 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60699_n_uu
[junit4:junit4] 2> 624282 T2435 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> 624282 T2422 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> 624282 T2415 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 624283 T2467 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 624282 T2451 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 624283 T2415 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> 624284 T2435 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 624284 T2451 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> 624288 T2468 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369523195435/collection1
[junit4:junit4] 2> 624288 T2468 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 624288 T2422 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 624288 T2468 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 624289 T2468 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 624291 T2468 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369523195435/collection1/'
[junit4:junit4] 2> 624292 T2468 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369523195435/collection1/lib/README' to classloader
[junit4:junit4] 2> 624292 T2468 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369523195435/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 624319 T2468 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 624352 T2468 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 624354 T2468 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 624358 T2468 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 624576 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 624576 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59841/n_uu",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:59841_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 624579 T2451 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> 624579 T2415 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> 624579 T2467 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> 624579 T2422 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> 624579 T2435 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> 624716 T2468 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 624722 T2468 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 624725 T2468 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 624733 T2468 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 624737 T2468 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 624740 T2468 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 624741 T2468 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 624741 T2468 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 624742 T2468 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 624743 T2468 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 624743 T2468 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 624743 T2468 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 624744 T2468 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty3-1369523195435/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/
[junit4:junit4] 2> 624744 T2468 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@fa441e07
[junit4:junit4] 2> 624744 T2468 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 624745 T2468 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3
[junit4:junit4] 2> 624745 T2468 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index/
[junit4:junit4] 2> 624746 T2468 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 624746 T2468 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index
[junit4:junit4] 2> 624747 T2468 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a288f44 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fec09cb3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 624748 T2468 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 624749 T2468 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 624750 T2468 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 624750 T2468 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 624751 T2468 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 624751 T2468 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 624752 T2468 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 624752 T2468 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 624753 T2468 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 624753 T2468 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 624754 T2468 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 624756 T2468 oass.SolrIndexSearcher.<init> Opening Searcher@6a20f023 main
[junit4:junit4] 2> 624756 T2468 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/tlog
[junit4:junit4] 2> 624757 T2468 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 624757 T2468 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 624761 T2469 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6a20f023 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 624762 T2468 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 624763 T2468 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 626083 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 626084 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60699/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:60699_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 626084 T2416 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 626085 T2416 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 626088 T2451 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> 626088 T2415 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> 626088 T2422 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> 626088 T2467 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> 626088 T2435 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> 626809 T2468 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 626809 T2468 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60699/n_uu collection:collection1 shard:shard1
[junit4:junit4] 2> 626811 T2468 oasc.ZkController.register We are http://127.0.0.1:60699/n_uu/collection1/ and leader is http://127.0.0.1:55419/n_uu/collection1/
[junit4:junit4] 2> 626812 T2468 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60699/n_uu
[junit4:junit4] 2> 626812 T2468 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 626812 T2468 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1296 name=collection1 org.apache.solr.core.SolrCore@ae0eb5cd url=http://127.0.0.1:60699/n_uu/collection1 node=127.0.0.1:60699_n_uu C1296_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:60699/n_uu, state=down, node_name=127.0.0.1:60699_n_uu, collection=collection1, core=collection1}
[junit4:junit4] 2> 626813 T2470 C1296 P60699 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 626813 T2468 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 626813 T2470 C1296 P60699 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 626814 T2470 C1296 P60699 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 626814 T2470 C1296 P60699 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 626814 T2393 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 626815 T2393 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 626815 T2470 C1296 P60699 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 626816 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 626822 T2428 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 626888 T2393 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 626890 T2393 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40285
[junit4:junit4] 2> 626891 T2393 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 626892 T2393 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 626892 T2393 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369523199123
[junit4:junit4] 2> 626893 T2393 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369523199123/solr.xml
[junit4:junit4] 2> 626893 T2393 oasc.CoreContainer.<init> New CoreContainer 1570074178
[junit4:junit4] 2> 626894 T2393 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369523199123/'
[junit4:junit4] 2> 626895 T2393 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369523199123/'
[junit4:junit4] 2> 626933 T2393 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 626934 T2393 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 626934 T2393 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 626935 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 626936 T2393 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 626936 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 626937 T2393 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 626937 T2393 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 626938 T2393 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 626939 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 626944 T2393 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 626945 T2393 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42389/solr
[junit4:junit4] 2> 626945 T2393 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 626946 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 626948 T2482 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@867b1d0a name:ZooKeeperConnection Watcher:127.0.0.1:42389 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 626948 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 626949 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 626955 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 626956 T2484 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7f5f1a5c name:ZooKeeperConnection Watcher:127.0.0.1:42389/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 626956 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 626959 T2393 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 627591 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 627591 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60699/n_uu",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:60699_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 627594 T2451 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> 627594 T2422 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> 627594 T2467 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> 627594 T2415 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> 627594 T2484 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> 627594 T2435 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> 627823 T2428 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 627823 T2428 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=4&wt=javabin&nodeName=127.0.0.1:60699_n_uu&core=collection1} status=0 QTime=1001
[junit4:junit4] 2> 627961 T2393 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40285_n_uu
[junit4:junit4] 2> 627963 T2393 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40285_n_uu
[junit4:junit4] 2> 627964 T2435 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> 627964 T2422 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> 627965 T2484 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 627964 T2451 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 627966 T2415 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 627966 T2484 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> 627964 T2467 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> 627967 T2415 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> 627966 T2435 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 627966 T2451 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> 627967 T2422 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 627969 T2467 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 627970 T2485 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369523199123/collection1
[junit4:junit4] 2> 627970 T2485 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 627971 T2485 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 627971 T2485 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 627972 T2485 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369523199123/collection1/'
[junit4:junit4] 2> 627973 T2485 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369523199123/collection1/lib/README' to classloader
[junit4:junit4] 2> 627973 T2485 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369523199123/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 627997 T2485 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 628026 T2485 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 628027 T2485 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 628031 T2485 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 628365 T2485 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 628370 T2485 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 628372 T2485 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 628381 T2485 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 628384 T2485 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 628388 T2485 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 628388 T2485 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 628389 T2485 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 628389 T2485 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 628390 T2485 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 628390 T2485 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 628391 T2485 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 628391 T2485 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty4-1369523199123/collection1/, dataDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/
[junit4:junit4] 2> 628391 T2485 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@fa441e07
[junit4:junit4] 2> 628392 T2485 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 628393 T2485 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4
[junit4:junit4] 2> 628393 T2485 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index/
[junit4:junit4] 2> 628393 T2485 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 628394 T2485 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index
[junit4:junit4] 2> 628395 T2485 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@fbfefbe6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ee96a8c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 628396 T2485 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 628397 T2485 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 628397 T2485 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 628398 T2485 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 628399 T2485 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 628399 T2485 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 628399 T2485 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 628400 T2485 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 628400 T2485 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 628401 T2485 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 628402 T2485 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 628404 T2485 oass.SolrIndexSearcher.<init> Opening Searcher@5b2fd5f4 main
[junit4:junit4] 2> 628404 T2485 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/tlog
[junit4:junit4] 2> 628405 T2485 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 628405 T2485 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 628409 T2486 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5b2fd5f4 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 628411 T2485 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 628411 T2485 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 629097 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 629098 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40285/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:40285_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 629098 T2416 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 629098 T2416 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 629102 T2451 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> 629102 T2415 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> 629102 T2467 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> 629102 T2435 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> 629102 T2422 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> 629104 T2484 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> 629412 T2485 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 629413 T2485 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40285/n_uu collection:collection1 shard:shard2
[junit4:junit4] 2> 629416 T2485 oasc.ZkController.register We are http://127.0.0.1:40285/n_uu/collection1/ and leader is http://127.0.0.1:59841/n_uu/collection1/
[junit4:junit4] 2> 629416 T2485 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40285/n_uu
[junit4:junit4] 2> 629417 T2485 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 629417 T2485 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1297 name=collection1 org.apache.solr.core.SolrCore@154a351 url=http://127.0.0.1:40285/n_uu/collection1 node=127.0.0.1:40285_n_uu C1297_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:40285/n_uu, state=down, node_name=127.0.0.1:40285_n_uu, collection=collection1, core=collection1}
[junit4:junit4] 2> 629418 T2487 C1297 P40285 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 629418 T2485 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 629418 T2487 C1297 P40285 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 629419 T2487 C1297 P40285 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 629420 T2487 C1297 P40285 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 629420 T2393 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 629421 T2393 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 629420 T2487 C1297 P40285 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 629421 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 629427 T2446 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 629428 T2393 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 629429 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 629435 T2429 oasc.CoreContainer.create Creating SolrCore 'onenodecollectioncore' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/onenodecollectioncore
[junit4:junit4] 2> 629435 T2429 oasc.ZkController.createCollectionZkNode Check for collection zkNode:onenodecollection
[junit4:junit4] 2> 629436 T2429 oasc.ZkController.createCollectionZkNode Creating collection in ZooKeeper:onenodecollection
[junit4:junit4] 2> 629437 T2429 oasc.ZkController.getConfName Looking for collection configName
[junit4:junit4] 2> 629438 T2429 oasc.ZkController.getConfName Only one config set found in zk - using it:conf1
[junit4:junit4] 2> 629438 T2429 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection
[junit4:junit4] 2> 629440 T2429 oasc.ZkController.readConfigName Load collection config from:/collections/onenodecollection
[junit4:junit4] 2> 629442 T2429 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/onenodecollectioncore/'
[junit4:junit4] 2> 629467 T2429 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 629498 T2429 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 629500 T2429 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 629504 T2429 oass.IndexSchema.readSchema [onenodecollectioncore] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C1298 name=collection1 org.apache.solr.core.SolrCore@ae0eb5cd url=http://127.0.0.1:60699/n_uu/collection1 node=127.0.0.1:60699_n_uu C1298_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:60699/n_uu, state=recovering, node_name=127.0.0.1:60699_n_uu, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 629824 T2470 C1298 P60699 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:55419/n_uu/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 629825 T2470 C1298 P60699 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:60699/n_uu START replicas=[http://127.0.0.1:55419/n_uu/collection1/] nUpdates=100
[junit4:junit4] 2> 629825 T2470 C1298 P60699 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 629825 T2470 C1298 P60699 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 629826 T2470 C1298 P60699 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 629826 T2470 C1298 P60699 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 629826 T2470 C1298 P60699 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 629826 T2470 C1298 P60699 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:55419/n_uu/collection1/. core=collection1
[junit4:junit4] 2> 629827 T2470 C1298 P60699 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1299 name=collection1 org.apache.solr.core.SolrCore@381cddd3 url=http://127.0.0.1:55419/n_uu/collection1 node=127.0.0.1:55419_n_uu C1299_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:55419/n_uu, state=active, node_name=127.0.0.1:55419_n_uu, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 629830 T2430 C1299 P55419 oasc.SolrCore.execute [collection1] webapp=/n_uu path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 629833 T2428 C1299 P55419 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 629834 T2428 C1299 P55419 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76c97554 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a058c8fb),segFN=segments_1,generation=1}
[junit4:junit4] 2> 629834 T2428 C1299 P55419 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 629835 T2428 C1299 P55419 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76c97554 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a058c8fb),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76c97554 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a058c8fb),segFN=segments_2,generation=2}
[junit4:junit4] 2> 629836 T2428 C1299 P55419 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 629837 T2428 C1299 P55419 oass.SolrIndexSearcher.<init> Opening Searcher@7b9eb241 realtime
[junit4:junit4] 2> 629837 T2428 C1299 P55419 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 629838 T2428 C1299 P55419 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_uu path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 6
[junit4:junit4] 2> 629839 T2470 C1298 P60699 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 629839 T2429 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 629839 T2470 C1298 P60699 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 629841 T2428 C1299 P55419 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 629841 T2428 C1299 P55419 oasc.SolrCore.execute [collection1] webapp=/n_uu path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 629842 T2470 C1298 P60699 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 629842 T2470 C1298 P60699 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 629842 T2470 C1298 P60699 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 629844 T2430 C1299 P55419 oasc.SolrCore.execute [collection1] webapp=/n_uu path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 629844 T2429 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 629844 T2470 C1298 P60699 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 629846 T2470 C1298 P60699 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index.20130526120642147
[junit4:junit4] 2> 629846 T2470 C1298 P60699 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@759f721c lockFactory=org.apache.lucene.store.NativeFSLockFactory@e13af816) fullCopy=false
[junit4:junit4] 2> 629847 T2429 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 629848 T2431 C1299 P55419 oasc.SolrCore.execute [collection1] webapp=/n_uu path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 629849 T2470 C1298 P60699 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 629849 T2470 C1298 P60699 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 629850 T2470 C1298 P60699 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 629851 T2470 C1298 P60699 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a288f44 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fec09cb3),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3a288f44 lockFactory=org.apache.lucene.store.NativeFSLockFactory@fec09cb3),segFN=segments_2,generation=2}
[junit4:junit4] 2> 629851 T2470 C1298 P60699 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 629851 T2470 C1298 P60699 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 629852 T2470 C1298 P60699 oass.SolrIndexSearcher.<init> Opening Searcher@25d31043 main
[junit4:junit4] 2> 629853 T2469 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@25d31043 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 629853 T2470 C1298 P60699 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index.20130526120642147 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index.20130526120642147;done=true>>]
[junit4:junit4] 2> 629854 T2470 C1298 P60699 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index.20130526120642147
[junit4:junit4] 2> 629854 T2470 C1298 P60699 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index.20130526120642147
[junit4:junit4] 2> 629854 T2470 C1298 P60699 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 629855 T2470 C1298 P60699 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 629855 T2470 C1298 P60699 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 629855 T2470 C1298 P60699 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 629856 T2470 C1298 P60699 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 629856 T2429 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 629862 T2429 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 629867 T2429 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 629868 T2429 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 629868 T2429 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 629869 T2429 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 629870 T2429 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 629871 T2429 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 629872 T2429 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 629872 T2429 oasc.SolrCore.<init> [onenodecollectioncore] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.BasicDistributedZk2Test-jetty1-1369523186383/onenodecollectioncore/, dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection/
[junit4:junit4] 2> 629873 T2429 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@fa441e07
[junit4:junit4] 2> 629874 T2429 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 629875 T2429 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection
[junit4:junit4] 2> 629876 T2429 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection/index/
[junit4:junit4] 2> 629877 T2429 oasc.SolrCore.initIndex WARN [onenodecollectioncore] Solr index directory '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 629878 T2429 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection/index
[junit4:junit4] 2> 629879 T2429 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4323d14 lockFactory=org.apache.lucene.store.NativeFSLockFactory@24b30352),segFN=segments_1,generation=1}
[junit4:junit4] 2> 629880 T2429 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 629882 T2429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 629883 T2429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 629884 T2429 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 629885 T2429 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 629886 T2429 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 629887 T2429 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 629887 T2429 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 629888 T2429 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 629889 T2429 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 629890 T2429 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 629892 T2429 oass.SolrIndexSearcher.<init> Opening Searcher@c8f6abe6 main
[junit4:junit4] 2> 629893 T2429 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection/tlog
[junit4:junit4] 2> 629894 T2429 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 629895 T2429 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 629898 T2491 oasc.SolrCore.registerSearcher [onenodecollectioncore] Registered new searcher Searcher@c8f6abe6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 629900 T2429 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 630606 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 630607 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40285/n_uu",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:40285_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 630609 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60699/n_uu",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:60699_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 630611 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55419/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55419_n_uu",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 630611 T2416 oasc.Overseer$ClusterStateUpdater.createCollection Create collection onenodecollection with numShards 1
[junit4:junit4] 2> 630612 T2416 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 630614 T2422 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> 630614 T2484 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> 630614 T2451 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> 630614 T2435 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> 630614 T2415 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> 630614 T2467 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> 630901 T2429 oasc.CoreContainer.registerCore registering core: onenodecollectioncore
[junit4:junit4] 2> 630902 T2429 oasc.ZkController.register Register replica - core:onenodecollectioncore address:http://127.0.0.1:55419/n_uu collection:onenodecollection shard:shard1
[junit4:junit4] 2> 630903 T2429 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leader_elect/shard1/election
[junit4:junit4] 2> 630909 T2429 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 630911 T2429 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 630912 T2429 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 630913 T2429 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55419/n_uu/onenodecollectioncore/
[junit4:junit4] 2> 630914 T2429 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 630915 T2429 oasc.SyncStrategy.syncToMe http://127.0.0.1:55419/n_uu/onenodecollectioncore/ has no replicas
[junit4:junit4] 2> 630916 T2429 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:55419/n_uu/onenodecollectioncore/
[junit4:junit4] 2> 630917 T2429 oascc.SolrZkClient.makePath makePath: /collections/onenodecollection/leaders/shard1
[junit4:junit4] 2> 631428 T2446 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 631428 T2446 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=5&wt=javabin&nodeName=127.0.0.1:40285_n_uu&core=collection1} status=0 QTime=2001
[junit4:junit4] 2> 632120 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 632126 T2451 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> 632126 T2415 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> 632126 T2467 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> 632126 T2422 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> 632126 T2435 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> 632126 T2484 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> 632174 T2429 oasc.ZkController.register We are http://127.0.0.1:55419/n_uu/onenodecollectioncore/ and leader is http://127.0.0.1:55419/n_uu/onenodecollectioncore/
[junit4:junit4] 2> 632174 T2429 oasc.ZkController.register No LogReplay needed for core=onenodecollectioncore baseURL=http://127.0.0.1:55419/n_uu
[junit4:junit4] 2> 632175 T2429 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 632175 T2429 oasc.ZkController.publish publishing core=onenodecollectioncore state=active
[junit4:junit4] 2> 632177 T2429 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 632178 T2429 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={dataDir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection&action=CREATE&version=2&numShards=1&name=onenodecollectioncore&wt=javabin&roles=none&collection=onenodecollection} status=0 QTime=2743
[junit4:junit4] 2> 632179 T2393 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: onenodecollection failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 632180 T2393 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 633182 T2393 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C1300 name=collection1 org.apache.solr.core.SolrCore@154a351 url=http://127.0.0.1:40285/n_uu/collection1 node=127.0.0.1:40285_n_uu C1300_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:40285/n_uu, state=recovering, node_name=127.0.0.1:40285_n_uu, collection=collection1, shard=shard2, core=collection1}
[junit4:junit4] 2> 633429 T2487 C1300 P40285 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:59841/n_uu/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 633430 T2487 C1300 P40285 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40285/n_uu START replicas=[http://127.0.0.1:59841/n_uu/collection1/] nUpdates=100
[junit4:junit4] 2> 633430 T2487 C1300 P40285 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 633430 T2487 C1300 P40285 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 633431 T2487 C1300 P40285 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 633431 T2487 C1300 P40285 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 633431 T2487 C1300 P40285 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 633432 T2487 C1300 P40285 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:59841/n_uu/collection1/. core=collection1
[junit4:junit4] 2> 633432 T2487 C1300 P40285 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1301 name=collection1 org.apache.solr.core.SolrCore@5f42eb96 url=http://127.0.0.1:59841/n_uu/collection1 node=127.0.0.1:59841_n_uu C1301_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:59841/n_uu, state=active, node_name=127.0.0.1:59841_n_uu, collection=collection1, shard=shard2, core=collection1, leader=true}
[junit4:junit4] 2> 633436 T2446 C1301 P59841 oasc.SolrCore.execute [collection1] webapp=/n_uu path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 633439 T2444 C1301 P59841 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 633441 T2444 C1301 P59841 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b07666d8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8565c54f),segFN=segments_1,generation=1}
[junit4:junit4] 2> 633442 T2444 C1301 P59841 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 633443 T2444 C1301 P59841 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b07666d8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8565c54f),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@b07666d8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8565c54f),segFN=segments_2,generation=2}
[junit4:junit4] 2> 633444 T2444 C1301 P59841 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 633446 T2444 C1301 P59841 oass.SolrIndexSearcher.<init> Opening Searcher@ad02acd1 realtime
[junit4:junit4] 2> 633447 T2444 C1301 P59841 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 633448 T2444 C1301 P59841 oasup.LogUpdateProcessor.finish [collection1] webapp=/n_uu path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 9
[junit4:junit4] 2> 633449 T2487 C1300 P40285 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 633449 T2487 C1300 P40285 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 633450 T2445 C1301 P59841 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 633451 T2445 C1301 P59841 oasc.SolrCore.execute [collection1] webapp=/n_uu path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 633452 T2487 C1300 P40285 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 633452 T2487 C1300 P40285 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 633452 T2487 C1300 P40285 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 633454 T2446 C1301 P59841 oasc.SolrCore.execute [collection1] webapp=/n_uu path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 633455 T2487 C1300 P40285 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 633455 T2487 C1300 P40285 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index.20130526120645757
[junit4:junit4] 2> 633456 T2487 C1300 P40285 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@12aabce2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a7c84e5b) fullCopy=false
[junit4:junit4] 2> 633457 T2444 C1301 P59841 oasc.SolrCore.execute [collection1] webapp=/n_uu path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=0
[junit4:junit4] 2> 633459 T2487 C1300 P40285 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 633460 T2487 C1300 P40285 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 633460 T2487 C1300 P40285 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 633461 T2487 C1300 P40285 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@fbfefbe6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ee96a8c),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@fbfefbe6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5ee96a8c),segFN=segments_2,generation=2}
[junit4:junit4] 2> 633462 T2487 C1300 P40285 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 633462 T2487 C1300 P40285 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 633463 T2487 C1300 P40285 oass.SolrIndexSearcher.<init> Opening Searcher@1add827e main
[junit4:junit4] 2> 633464 T2486 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1add827e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 633464 T2487 C1300 P40285 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index.20130526120645757 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index.20130526120645757;done=true>>]
[junit4:junit4] 2> 633464 T2487 C1300 P40285 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index.20130526120645757
[junit4:junit4] 2> 633465 T2487 C1300 P40285 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index.20130526120645757
[junit4:junit4] 2> 633465 T2487 C1300 P40285 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 633465 T2487 C1300 P40285 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 633466 T2487 C1300 P40285 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 633466 T2487 C1300 P40285 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 633479 T2487 C1300 P40285 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 633631 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 633632 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55419/n_uu",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:55419_n_uu_onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:55419_n_uu",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 633636 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40285/n_uu",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:40285_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 633640 T2451 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> 633640 T2422 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> 633640 T2435 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> 633640 T2415 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> 633640 T2467 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> 633640 T2484 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> 634184 T2393 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 634185 T2393 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: onenodecollection
[junit4:junit4] 2> 634186 T2393 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 634196 T2393 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 634197 T2495 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@71e4449b name:ZooKeeperConnection Watcher:127.0.0.1:42389 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 634198 T2393 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 634232 T2393 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 52302
[junit4:junit4] 2> 634232 T2393 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=58847713
[junit4:junit4] 2> 635145 T2416 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 635146 T2416 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52302/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52302_n_uu",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 635149 T2451 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> 635149 T2435 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> 635149 T2467 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> 635149 T2484 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> 635149 T2415 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> 636234 T2393 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 636235 T2393 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 636236 T2393 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@eb0bfb9d
[junit4:junit4] 2> 636239 T2393 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> 636240 T2393 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 636240 T2393 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 636241 T2393 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 636241 T2393 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 636242 T2393 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 636243 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data;done=false>>]
[junit4:junit4] 2> 636243 T2393 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data
[junit4:junit4] 2> 636244 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data/index;done=false>>]
[junit4:junit4] 2> 636244 T2393 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/control/data/index
[junit4:junit4] 2> 636245 T2416 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89753071320694787-127.0.0.1:52302_n_uu-n_0000000000) am no longer a leader.
[junit4:junit4] 2> 636246 T2467 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> 636246 T2484 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 636246 T2451 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 636247 T2484 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> 636247 T2467 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 636247 T2451 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> 636247 T2435 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 636250 T2435 oasc.Overseer.start Overseer (id=89753071320694790-127.0.0.1:55419_n_uu-n_0000000001) starting
[junit4:junit4] 2> 636255 T2435 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> 636255 T2497 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 636256 T2496 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 636257 T2435 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 636258 T2496 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 636259 T2496 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52302/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:52302_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 636266 T2393 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/n_uu,null}
[junit4:junit4] 2> 636278 T2435 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> 636278 T2484 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> 636278 T2467 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> 636278 T2451 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> 636318 T2393 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 55419
[junit4:junit4] 2> 636319 T2393 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=2013579373
[junit4:junit4] 2> 637546 T2415 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 637546 T2415 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> 637547 T2415 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 637782 T2496 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 637783 T2496 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55419/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:55419_n_uu_onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:55419_n_uu",
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 637786 T2496 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55419/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:55419_n_uu",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 637789 T2435 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> 637789 T2451 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> 637789 T2484 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> 637789 T2467 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> 639321 T2393 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 639321 T2393 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 639323 T2393 oasc.ZkController.publish publishing core=onenodecollectioncore state=down
[junit4:junit4] 2> 639324 T2393 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@381cddd3
[junit4:junit4] 2> 639327 T2393 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> 639328 T2393 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 639328 T2393 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 639329 T2393 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 639330 T2393 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 639331 T2393 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 639331 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1/index;done=false>>]
[junit4:junit4] 2> 639332 T2393 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1/index
[junit4:junit4] 2> 639332 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1;done=false>>]
[junit4:junit4] 2> 639333 T2393 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty1
[junit4:junit4] 2> 639334 T2393 oasc.SolrCore.close [onenodecollectioncore] CLOSING SolrCore org.apache.solr.core.SolrCore@4afae388
[junit4:junit4] 2> 639338 T2393 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> 639339 T2393 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 639339 T2393 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 639340 T2393 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 639341 T2393 oasc.SolrCore.closeSearcher [onenodecollectioncore] Closing main searcher on request.
[junit4:junit4] 2> 639341 T2393 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 639342 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection/index;done=false>>]
[junit4:junit4] 2> 639342 T2393 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection/index
[junit4:junit4] 2> 639343 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection;done=false>>]
[junit4:junit4] 2> 639343 T2393 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-BasicDistributedZk2Test-1369523182991/onenodecollection
[junit4:junit4] 2> 639344 T2496 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89753071320694790-127.0.0.1:55419_n_uu-n_0000000001) am no longer a leader.
[junit4:junit4] 2> 639345 T2435 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> 639345 T2467 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> 639345 T2435 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 639345 T2484 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 639346 T2435 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 639346 T2484 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> 639347 T2467 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 639346 T2451 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 639348 T2467 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 639349 T2451 oasc.Overseer.start Overseer (id=89753071320694792-127.0.0.1:59841_n_uu-n_0000000002) starting
[junit4:junit4] 2> 639350 T2467 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 639350 T2467 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 639350 T2467 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 639350 T2467 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60699/n_uu/collection1/
[junit4:junit4] 2> 639351 T2467 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 639351 T2467 oasc.SyncStrategy.syncToMe http://127.0.0.1:60699/n_uu/collection1/ has no replicas
[junit4:junit4] 2> 639351 T2467 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60699/n_uu/collection1/
[junit4:junit4] 2> 639352 T2467 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 639366 T2393 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/n_uu,null}
[junit4:junit4] 2> 639371 T2499 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 639372 T2451 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 639372 T2451 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> 639373 T2498 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 639376 T2498 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 639377 T2498 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55419/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:55419_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 639380 T2498 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55419/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:55419_n_uu_onenodecollectioncore",
[junit4:junit4] 2> "node_name":"127.0.0.1:55419_n_uu",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":"none",
[junit4:junit4] 2> "collection":"onenodecollection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"onenodecollectioncore"}
[junit4:junit4] 2> 639391 T2451 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> 639391 T2484 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> 639391 T2467 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> 639418 T2393 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 59841
[junit4:junit4] 2> 639419 T2393 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-681137677
[junit4:junit4] 2> 640420 T2393 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 640421 T2393 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 640423 T2393 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@5f42eb96
[junit4:junit4] 2> 640425 T2393 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> 640426 T2393 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 640427 T2393 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 640427 T2393 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 640428 T2393 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 640429 T2393 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 640429 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2;done=false>>]
[junit4:junit4] 2> 640430 T2393 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2
[junit4:junit4] 2> 640430 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2/index;done=false>>]
[junit4:junit4] 2> 640431 T2393 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty2/index
[junit4:junit4] 2> 640431 T2498 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89753071320694792-127.0.0.1:59841_n_uu-n_0000000002) am no longer a leader.
[junit4:junit4] 2> 640433 T2484 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 640433 T2467 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 640435 T2484 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 640435 T2484 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 640435 T2484 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 640435 T2467 oasc.Overseer.start Overseer (id=89753071320694794-127.0.0.1:60699_n_uu-n_0000000003) starting
[junit4:junit4] 2> 640436 T2484 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40285/n_uu/collection1/
[junit4:junit4] 2> 640436 T2484 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40285/n_uu START replicas=[http://127.0.0.1:59841/n_uu/collection1/] nUpdates=100
[junit4:junit4] 2> 640437 T2484 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40285/n_uu DONE. We have no versions. sync failed.
[junit4:junit4] 2> 640437 T2484 oasc.SyncStrategy.syncReplicas Leader's attempt to sync with shard failed, moving to the next canidate
[junit4:junit4] 2> 640437 T2484 oasc.ShardLeaderElectionContext.runLeaderProcess We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4:junit4] 2> 640438 T2484 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:40285/n_uu/collection1/
[junit4:junit4] 2> 640438 T2484 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 640439 T2467 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> 640439 T2502 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 640439 T2501 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 640440 T2467 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 640441 T2484 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 640441 T2501 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 640442 T2484 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> 640442 T2501 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59841/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:59841_n_uu",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 640443 T2393 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/n_uu,null}
[junit4:junit4] 2> 640445 T2501 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59841/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:59841_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 640453 T2467 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> 640454 T2484 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> 640495 T2393 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 60699
[junit4:junit4] 2> 640496 T2393 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=-489540076
[junit4:junit4] 2> 641497 T2393 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 641498 T2393 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 641500 T2393 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@ae0eb5cd
[junit4:junit4] 2> 641503 T2393 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> 641504 T2393 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 641504 T2393 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 641505 T2393 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 641506 T2393 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 641506 T2393 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 641507 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3;done=false>>]
[junit4:junit4] 2> 641507 T2393 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3
[junit4:junit4] 2> 641508 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index;done=false>>]
[junit4:junit4] 2> 641509 T2393 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty3/index
[junit4:junit4] 2> 641509 T2501 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89753071320694794-127.0.0.1:60699_n_uu-n_0000000003) am no longer a leader.
[junit4:junit4] 2> 641510 T2467 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> 641510 T2467 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 641510 T2484 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4] 2> 641511 T2467 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 641511 T2484 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> 641512 T2484 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 641514 T2484 oasc.Overseer.start Overseer (id=89753071320694796-127.0.0.1:40285_n_uu-n_0000000004) starting
[junit4:junit4] 2> 641517 T2504 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 641517 T2503 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 641519 T2503 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 641519 T2503 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60699/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:60699_n_uu",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 641521 T2503 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60699/n_uu",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:60699_n_uu",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 641523 T2484 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> 641530 T2393 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/n_uu,null}
[junit4:junit4] 2> 641583 T2393 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 40285
[junit4:junit4] 2> 641583 T2393 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1570074178
[junit4:junit4] 2> 641732 T2451 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 641733 T2451 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> 641733 T2451 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 642585 T2393 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 642586 T2393 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 642591 T2393 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@154a351
[junit4:junit4] 2> 642599 T2393 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> 642600 T2393 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 642601 T2393 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 642601 T2393 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 642602 T2393 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 642603 T2393 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 642604 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4;done=false>>]
[junit4:junit4] 2> 642604 T2393 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4
[junit4:junit4] 2> 642605 T2393 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index;done=false>>]
[junit4:junit4] 2> 642606 T2393 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.BasicDistributedZk2Test-1369523182991/jetty4/index
[junit4:junit4] 2> 642607 T2503 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89753071320694796-127.0.0.1:40285_n_uu-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 642628 T2393 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/n_uu,null}
[junit4:junit4] 2> 642685 T2393 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 642686 T2393 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:42389 42389
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> / (2)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1> /solr (7)
[junit4:junit4] 1> /solr/configs (1)
[junit4:junit4] 1> /solr/configs/conf1 (9)
[junit4:junit4] 1> /solr/configs/conf1/old_synonyms.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/protwords.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/stopwords.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/synonyms.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/schema.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/currency.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/open-exchange-rates.json (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "disclaimer": "This data is not real, it was synthetically created to match currency.xml. It is modeled after the data format available from openexchangerates.org. See https://openexchangerates.org/documentation for details",
[junit4:junit4] 1> "license": "http://www.apache.org/licenses/LICENSE-2.0",
[junit4:junit4] 1> "timestamp": 1332070464,
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 1> "IMPORTANT NOTE": "In order for tests to work, this data must be kept in sync with ./currency.xml",
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 1> "base": "USD",
[junit4:junit4] 1> "rates": {
[junit4:junit4] 1> "USD": 1,
[junit4:junit4] 1> "JPY": 81.29,
[junit4:junit4] 1> "EUR": 2.5,
[junit4:junit4] 1> "GBP": 0.5,
[junit4:junit4] 1> "MXN": 2.0
[junit4:junit4] 1> }
[junit4:junit4] 1> }
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/configs/conf1/solrconfig.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/mapping-ISOLatin1Accent.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/overseer (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/overseer/queue (0)
[junit4:junit4] 1> /solr/overseer/collection-queue-work (0)
[junit4:junit4] 1> /solr/overseer/queue-work (0)
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89753071320694787-127.0.0.1:52302_n_uu-n_0000000000"}
[junit4:junit4] 1> /solr/overseer_elect/election (5)
[junit4:junit4] 1> /solr/overseer_elect/election/89753071320694796-127.0.0.1:40285_n_uu-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89753071320694792-127.0.0.1:59841_n_uu-n_0000000002 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89753071320694790-127.0.0.1:55419_n_uu-n_0000000001 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89753071320694787-127.0.0.1:52302_n_uu-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89753071320694794-127.0.0.1:60699_n_uu-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections (3)
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leade
[...truncated too long message...]
junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
[junit4:junit4] 2> at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
[junit4:junit4] 2> at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4:junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] 2>
[junit4:junit4] 2> 1056752 T3704 oas.SolrTestCaseJ4.tearDown ###Ending testCommitWithin
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=HardAutoCommitTest -Dtests.method=testCommitWithin -Dtests.seed=E3057B1F8FCF161F -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=pt_BR -Dtests.timezone=PNT -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 5.00s J0 | HardAutoCommitTest.testCommitWithin <<<
[junit4:junit4] > Throwable #1: java.lang.RuntimeException: Exception during query
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([E3057B1F8FCF161F:59D714670CE1F80A]:0)
[junit4:junit4] > at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:525)
[junit4:junit4] > at org.apache.solr.update.HardAutoCommitTest.testCommitWithin(HardAutoCommitTest.java:79)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] > Caused by: java.lang.RuntimeException: REQUEST FAILED: xpath=//result[@numFound=0]
[junit4:junit4] > xml response was: <?xml version="1.0" encoding="UTF-8"?>
[junit4:junit4] > <response>
[junit4:junit4] > <lst name="responseHeader"><int name="status">0</int><int name="QTime">3168</int></lst><result name="response" numFound="1" start="0"><doc><int name="id">529</int><int name="range_facet_si">529</int><arr name="range_facet_l"><long>529</long></arr><arr name="range_facet_sl"><long>529</long></arr><arr name="field_t"><str>what's inside?</str></arr><arr name="subject"><str>info</str></arr><int name="intDefault">42</int><date name="timestamp">2013-05-25T23:13:45.843Z</date><arr name="multiDefault"><str>muLti-Default</str></arr></doc></result>
[junit4:junit4] > </response>
[junit4:junit4] > request was:q=id:529&start=0&qt=standard&version=2.2&rows=20
[junit4:junit4] > at org.apache.solr.SolrTestCaseJ4.assertQ(SolrTestCaseJ4.java:518)
[junit4:junit4] > ... 41 more
[junit4:junit4] 2> 1056762 T3704 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 1056762 T3704 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=35505764
[junit4:junit4] 2> 1056763 T3704 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@c0765d03
[junit4:junit4] 2> 1056774 T3704 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=1,autocommits=1,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=1,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 1056777 T3704 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1056778 T3704 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1056779 T3704 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1056782 T3704 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1056783 T3704 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1056783 T3704 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-HardAutoCommitTest-1369523623374 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-HardAutoCommitTest-1369523623374;done=false>>]
[junit4:junit4] 2> 1056784 T3704 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-HardAutoCommitTest-1369523623374
[junit4:junit4] 2> 1056785 T3704 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-HardAutoCommitTest-1369523623374/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-HardAutoCommitTest-1369523623374/index;done=false>>]
[junit4:junit4] 2> 1056785 T3704 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-HardAutoCommitTest-1369523623374/index
[junit4:junit4] 2> NOTE: test params are: codec=Asserting, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=pt_BR, timezone=PNT
[junit4:junit4] 2> NOTE: Linux 3.2.0-41-generic x86/IBM Corporation 1.7.0 (32-bit)/cpus=8,threads=1,free=76942144,total=201195520
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestFieldCollectionResource, CircularListTest, TestDynamicFieldCollectionResource, PrimitiveFieldTypeTest, SOLR749Test, BadComponentTest, CoreAdminHandlerTest, ShardRoutingTest, TestMaxScoreQueryParser, ResourceLoaderTest, TestQueryUtils, TestCloudManagedSchema, TestUniqueKeyFieldResource, PreAnalyzedFieldTest, PluginInfoTest, ClusterStateUpdateTest, TestManagedSchemaFieldResource, FileBasedSpellCheckerTest, AnalysisAfterCoreReloadTest, IndexSchemaTest, WordBreakSolrSpellCheckerTest, SchemaVersionSpecificBehaviorTest, SolrCoreTest, SuggesterFSTTest, PeerSyncTest, AlternateDirectoryTest, FastVectorHighlighterTest, TestJoin, RAMDirectoryFactoryTest, StatelessScriptUpdateProcessorFactoryTest, TestPseudoReturnFields, TestXIncludeConfig, TestCharFilters, TestFuzzyAnalyzedSuggestions, TestPluginEnable, TestSort, TestDocSet, DirectUpdateHandlerOptimizeTest, TestConfig, TestDynamicFieldResource, TestTrie, TestCopyFieldCollectionResource, ZkControllerTest, SuggesterTest, UUIDFieldTest, MBeansHandlerTest, TestSolrQueryParserDefaultOperatorResource, PolyFieldTest, CSVRequestHandlerTest, TestFaceting, SliceStateTest, FieldMutatingUpdateProcessorTest, TestRandomDVFaceting, TestClassNameShortening, TestSurroundQueryParser, ReturnFieldsTest, TestFastWriter, BadCopyFieldTest, DistributedSpellCheckComponentTest, TestSolrDeletionPolicy1, TestSolrCoreProperties, TestPropInjectDefaults, TestReversedWildcardFilterFactory, LukeRequestHandlerTest, TestRemoteStreaming, DocValuesTest, DateFieldTest, UpdateRequestProcessorFactoryTest, TestSweetSpotSimilarityFactory, TestReplicationHandler, CacheHeaderTest, SpellingQueryConverterTest, BasicDistributedZkTest, BasicDistributedZk2Test, UnloadDistributedZkTest, SyncSliceTest, OverseerTest, BasicZkTest, TestRandomFaceting, TestRecovery, TestRealTimeGet, HardAutoCommitTest]
[junit4:junit4] Completed on J0 in 5.76s, 1 test, 1 error <<< FAILURES!
[...truncated 403 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:380: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:373: 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:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1240: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:884: There were test failures: 295 suites, 1231 tests, 2 errors, 14 ignored (8 assumptions)
Total time: 45 minutes 9 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure