lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Chris Hostetter <hossman_luc...@fucit.org>
Subject Re: [JENKINS] Lucene-Solr-NightlyTests-trunk - Build # 696 - Still Failing
Date Fri, 29 May 2015 18:20:05 GMT

I've updated SOLR-7603 with the new details from the 
UpdateRequestProcessorFactoryTest failure and will try to make sense of 
that.

Anybody have any clue what's up with the HttpPartitionTest test here?

leaking file handles on the segments file?


: Date: Fri, 29 May 2015 09:42:29 +0000 (UTC)
: From: Apache Jenkins Server <jenkins@builds.apache.org>
: Reply-To: dev@lucene.apache.org
: To: dev@lucene.apache.org
: Subject: [JENKINS] Lucene-Solr-NightlyTests-trunk - Build # 696 - Still
:     Failing
: 
: Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-trunk/696/
: 
: 3 tests failed.
: FAILED:  junit.framework.TestSuite.org.apache.solr.cloud.HttpPartitionTest
: 
: Error Message:
: file handle leaks: [SeekableByteChannel(/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/temp/solr.cloud.HttpPartitionTest 3AF6852C6379681-001/index-SimpleFSDirectory-011/segments_2)]
: 
: Stack Trace:
: java.lang.RuntimeException: file handle leaks: [SeekableByteChannel(/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/temp/solr.cloud.HttpPartitionTest 3AF6852C6379681-001/index-SimpleFSDirectory-011/segments_2)]
: 	at __randomizedtesting.SeedInfo.seed([3AF6852C6379681]:0)
: 	at org.apache.lucene.mockfile.LeakFS.onClose(LeakFS.java:64)
: 	at org.apache.lucene.mockfile.FilterFileSystem.close(FilterFileSystem.java:78)
: 	at org.apache.lucene.mockfile.FilterFileSystem.close(FilterFileSystem.java:79)
: 	at org.apache.lucene.util.TestRuleTemporaryFilesCleanup.afterAlways(TestRuleTemporaryFilesCleanup.java:227)
: 	at com.carrotsearch.randomizedtesting.rules.TestRuleAdapter$1.afterAlways(TestRuleAdapter.java:31)
: 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:43)
: 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
: 	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:54)
: 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
: 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
: 	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:365)
: 	at java.lang.Thread.run(Thread.java:745)
: Caused by: java.lang.Exception
: 	at org.apache.lucene.mockfile.LeakFS.onOpen(LeakFS.java:47)
: 	at org.apache.lucene.mockfile.HandleTrackingFS.callOpenHook(HandleTrackingFS.java:82)
: 	at org.apache.lucene.mockfile.HandleTrackingFS.newByteChannel(HandleTrackingFS.java:272)
: 	at org.apache.lucene.mockfile.FilterFileSystemProvider.newByteChannel(FilterFileSystemProvider.java:213)
: 	at org.apache.lucene.mockfile.HandleTrackingFS.newByteChannel(HandleTrackingFS.java:241)
: 	at java.nio.file.Files.newByteChannel(Files.java:361)
: 	at java.nio.file.Files.newByteChannel(Files.java:407)
: 	at org.apache.lucene.store.SimpleFSDirectory.openInput(SimpleFSDirectory.java:76)
: 	at org.apache.lucene.store.Directory.openChecksumInput(Directory.java:110)
: 	at org.apache.lucene.store.RawDirectoryWrapper.openChecksumInput(RawDirectoryWrapper.java:42)
: 	at org.apache.lucene.index.SegmentInfos.readCommit(SegmentInfos.java:269)
: 	at org.apache.lucene.index.CheckIndex.checkIndex(CheckIndex.java:488)
: 	at org.apache.lucene.util.TestUtil.checkIndex(TestUtil.java:278)
: 	at org.apache.lucene.util.TestUtil.checkIndex(TestUtil.java:265)
: 	at org.apache.lucene.store.BaseDirectoryWrapper.close(BaseDirectoryWrapper.java:46)
: 	at org.apache.solr.core.CachingDirectoryFactory.close(CachingDirectoryFactory.java:307)
: 	at org.apache.solr.core.CachingDirectoryFactory.closeCacheValue(CachingDirectoryFactory.java:273)
: 	at org.apache.solr.core.CachingDirectoryFactory.close(CachingDirectoryFactory.java:203)
: 	at org.apache.solr.core.SolrCore.close(SolrCore.java:1254)
: 	at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:311)
: 	at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:198)
: 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:159)
: 	at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:348)
: 	at org.apache.solr.cloud.ZkController.joinElection(ZkController.java:1070)
: 	at org.apache.solr.cloud.ZkController.register(ZkController.java:884)
: 	at org.apache.solr.cloud.ZkController$RegisterCoreAsync.call(ZkController.java:225)
: 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
: 	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor$1.run(ExecutorUtil.java:156)
: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
: 	... 1 more
: 
: 
: REGRESSION:  org.apache.solr.update.processor.UpdateRequestProcessorFactoryTest.testUpdateDistribChainSkipping
: 
: Error Message:
: distrib-chain-explicit expected LogUpdateProcessor in chain due to @RunAllways, but not found: org.apache.solr.update.processor.DistributedUpdateProcessor@638c6e19, org.apache.solr.update.processor.RemoveBlankFieldUpdateProcessorFactory$1@25bbdfcb, org.apache.solr.update.processor.RunUpdateProcessor@473fea05, 
: 
: Stack Trace:
: java.lang.AssertionError: distrib-chain-explicit expected LogUpdateProcessor in chain due to @RunAllways, but not found: org.apache.solr.update.processor.DistributedUpdateProcessor@638c6e19, org.apache.solr.update.processor.RemoveBlankFieldUpdateProcessorFactory$1@25bbdfcb, org.apache.solr.update.processor.RunUpdateProcessor@473fea05, 
: 	at __randomizedtesting.SeedInfo.seed([3AF6852C6379681:724B9684B0DCB14D]:0)
: 	at org.junit.Assert.fail(Assert.java:93)
: 	at org.junit.Assert.assertTrue(Assert.java:43)
: 	at org.apache.solr.update.processor.UpdateRequestProcessorFactoryTest.testUpdateDistribChainSkipping(UpdateRequestProcessorFactoryTest.java:127)
: 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
: 	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
: 	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
: 	at java.lang.reflect.Method.invoke(Method.java:483)
: 	at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1627)
: 	at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:836)
: 	at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:872)
: 	at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:886)
: 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
: 	at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
: 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
: 	at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
: 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
: 	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:365)
: 	at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798)
: 	at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458)
: 	at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:845)
: 	at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:747)
: 	at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:781)
: 	at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:792)
: 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
: 	at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
: 	at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
: 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
: 	at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
: 	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 com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
: 	at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
: 	at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:54)
: 	at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
: 	at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
: 	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:365)
: 	at java.lang.Thread.run(Thread.java:745)
: 
: 
: FAILED:  org.apache.solr.cloud.CollectionsAPIDistributedZkTest.test
: 
: Error Message:
: Captured an uncaught exception in thread: Thread[id=3840, name=collection5, state=RUNNABLE, group=TGRP-CollectionsAPIDistributedZkTest]
: 
: Stack Trace:
: com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=3840, name=collection5, state=RUNNABLE, group=TGRP-CollectionsAPIDistributedZkTest]
: Caused by: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:44466/xk/t: collection already exists: awholynewstresscollection_collection5_1
: 	at __randomizedtesting.SeedInfo.seed([3AF6852C6379681]:0)
: 	at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:560)
: 	at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:235)
: 	at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:227)
: 	at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:376)
: 	at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:328)
: 	at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1086)
: 	at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:856)
: 	at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:799)
: 	at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1220)
: 	at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1570)
: 	at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1591)
: 	at org.apache.solr.cloud.CollectionsAPIDistributedZkTest$1CollectionThread.run(CollectionsAPIDistributedZkTest.java:860)
: 
: 
: 
: 
: Build Log:
: [...truncated 10189 lines...]
:    [junit4] Suite: org.apache.solr.cloud.CollectionsAPIDistributedZkTest
:    [junit4]   2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/init-core-data-001
:    [junit4]   2> 401841 INFO  (SUITE-CollectionsAPIDistributedZkTest-seed#[3AF6852C6379681]-worker) [    ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (true)
:    [junit4]   2> 401841 INFO  (SUITE-CollectionsAPIDistributedZkTest-seed#[3AF6852C6379681]-worker) [    ] o.a.s.BaseDistributedSearchTestCase Setting hostContext system property: /xk/t
:    [junit4]   2> 401844 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
:    [junit4]   2> 401845 INFO  (Thread-2385) [    ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
:    [junit4]   2> 401845 INFO  (Thread-2385) [    ] o.a.s.c.ZkTestServer Starting server
:    [junit4]   2> 401945 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.ZkTestServer start zk server on port:38050
:    [junit4]   2> 401959 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
:    [junit4]   2> 401961 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
:    [junit4]   2> 401963 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
:    [junit4]   2> 401965 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
:    [junit4]   2> 401967 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
:    [junit4]   2> 401968 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
:    [junit4]   2> 401970 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
:    [junit4]   2> 401971 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
:    [junit4]   2> 401973 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
:    [junit4]   2> 401974 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
:    [junit4]   2> 401976 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractZkTestCase put /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/core/src/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
:    [junit4]   2> 402265 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores/collection1
:    [junit4]   2> 402267 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.e.j.s.Server jetty-9.2.10.v20150310
:    [junit4]   2> 402269 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2bd76d64{/xk/t,null,AVAILABLE}
:    [junit4]   2> 402288 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.e.j.s.ServerConnector Started ServerConnector@19fab22b{HTTP/1.1}{127.0.0.1:60774}
:    [junit4]   2> 402288 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.e.j.s.Server Started @405784ms
:    [junit4]   2> 402289 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/tempDir-001/control/data, hostContext=/xk/t, hostPort=60774, coreRootDirectory=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores}
:    [junit4]   2> 402289 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.s.SolrDispatchFilter SolrDispatchFilter.init()sun.misc.Launcher$AppClassLoader@c387f44
:    [junit4]   2> 402289 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.SolrResourceLoader new SolrResourceLoader for directory: '/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/'
:    [junit4]   2> 402303 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/solr.xml
:    [junit4]   2> 402308 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.CoresLocator Config-defined core root directory: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores
:    [junit4]   2> 402308 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.CoreContainer New CoreContainer 1809701273
:    [junit4]   2> 402309 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.CoreContainer Loading cores into CoreContainer [instanceDir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/]
:    [junit4]   2> 402309 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.CoreContainer loading shared library: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/lib
:    [junit4]   2> 402309 WARN  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.SolrResourceLoader Can't find (or read) directory to add to classloader: lib (resolved as: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/lib).
:    [junit4]   2> 402315 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.h.c.HttpShardHandlerFactory created with socketTimeout : 90000,urlScheme : ,connTimeout : 15000,maxConnectionsPerHost : 20,maxConnections : 10000,corePoolSize : 0,maximumPoolSize : 2147483647,maxThreadIdleTime : 5,sizeOfQueue : -1,fairnessPolicy : false,useRetries : false,
:    [junit4]   2> 402317 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
:    [junit4]   2> 402317 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.l.LogWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
:    [junit4]   2> 402317 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.l.LogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
:    [junit4]   2> 402317 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:38050/solr
:    [junit4]   2> 402318 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.ZkController zkHost includes chroot
:    [junit4]   2> 402340 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60774_xk%2Ft
:    [junit4]   2> 402353 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.Overseer Overseer (id=null) closing
:    [junit4]   2> 402354 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:60774_xk%2Ft
:    [junit4]   2> 402355 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.Overseer Overseer (id=93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) starting
:    [junit4]   2> 402363 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.OverseerAutoReplicaFailoverThread Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=10000 autoReplicaFailoverBadNodeExpiration=60000
:    [junit4]   2> 402363 INFO  (OverseerCollectionProcessor-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.OverseerCollectionProcessor Process current queue of collection creations
:    [junit4]   2> 402364 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.Overseer Starting to work on the main queue
:    [junit4]   2> 402366 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.CoreContainer No authentication plugin used.
:    [junit4]   2> 402367 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.CoreContainer Security conf doesn't exist. Skipping setup for authorization module.
:    [junit4]   2> 402367 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.CoresLocator Looking for core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores
:    [junit4]   2> 402368 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.SolrCore Created CoreDescriptor: {name=collection1, config=solrconfig.xml, transient=false, schema=schema.xml, loadOnStartup=true, instanceDir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores/collection1, collection=control_collection, absoluteInstDir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores/collection1/, coreNodeName=, dataDir=data/,
  shard=}
:    [junit4]   2> 402368 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.CoresLocator Found core collection1 in /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores/collection1/
:    [junit4]   2> 402369 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.CoresLocator Found 1 core definitions
:    [junit4]   2> 402369 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.ZkController publishing state=down
:    [junit4]   2> 402369 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.ZkController numShards not found on descriptor - reading it from system property
:    [junit4]   2> 402369 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.s.SolrDispatchFilter user.dir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1
:    [junit4]   2> 402370 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.s.SolrDispatchFilter SolrDispatchFilter.init() done
:    [junit4]   2> 402370 INFO  (zkCallback-227-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.DistributedQueue NodeChildrenChanged fired on path /overseer/queue state SyncConnected
:    [junit4]   2> 402370 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.ZkController look for our core node name
:    [junit4]   2> 402371 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
:    [junit4]   2>   "core":"collection1",
:    [junit4]   2>   "roles":null,
:    [junit4]   2>   "base_url":"http://127.0.0.1:60774/xk/t",
:    [junit4]   2>   "node_name":"127.0.0.1:60774_xk%2Ft",
:    [junit4]   2>   "numShards":"1",
:    [junit4]   2>   "state":"down",
:    [junit4]   2>   "shard":null,
:    [junit4]   2>   "collection":"control_collection",
:    [junit4]   2>   "operation":"state"} current state version: 0
:    [junit4]   2> 402371 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.o.ReplicaMutator Update state numShards=1 message={
:    [junit4]   2>   "core":"collection1",
:    [junit4]   2>   "roles":null,
:    [junit4]   2>   "base_url":"http://127.0.0.1:60774/xk/t",
:    [junit4]   2>   "node_name":"127.0.0.1:60774_xk%2Ft",
:    [junit4]   2>   "numShards":"1",
:    [junit4]   2>   "state":"down",
:    [junit4]   2>   "shard":null,
:    [junit4]   2>   "collection":"control_collection",
:    [junit4]   2>   "operation":"state"}
:    [junit4]   2> 402371 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.o.ClusterStateMutator building a new cName: control_collection
:    [junit4]   2> 402372 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
:    [junit4]   2> 403370 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.ZkController waiting to find shard id in clusterstate for collection1
:    [junit4]   2> 403371 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.ZkController Check for collection zkNode:control_collection
:    [junit4]   2> 403371 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.ZkController Collection zkNode exists
:    [junit4]   2> 403372 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.SolrResourceLoader new SolrResourceLoader for directory: '/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores/collection1/'
:    [junit4]   2> 403384 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.Config loaded config solrconfig.xml with version 0 
:    [junit4]   2> 403393 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.SolrConfig current version of requestparams : -1
:    [junit4]   2> 403396 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.0.0
:    [junit4]   2> 403404 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.Config Loaded SolrConfig: solrconfig.xml
:    [junit4]   2> 403405 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.IndexSchema Reading Solr Schema from /configs/conf1/schema.xml
:    [junit4]   2> 403410 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
:    [junit4]   2> 403498 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
:    [junit4]   2> 403504 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.IndexSchema default search field in schema is text
:    [junit4]   2> 403505 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.IndexSchema unique key field: id
:    [junit4]   2> 403514 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.FileExchangeRateProvider Reloading exchange rates from file currency.xml
:    [junit4]   2> 403517 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.FileExchangeRateProvider Reloading exchange rates from file currency.xml
:    [junit4]   2> 403518 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Reloading exchange rates from open-exchange-rates.json
:    [junit4]   2> 403519 WARN  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Unknown key IMPORTANT NOTE
:    [junit4]   2> 403519 WARN  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Expected key, got STRING
:    [junit4]   2> 403519 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Reloading exchange rates from open-exchange-rates.json
:    [junit4]   2> 403520 WARN  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Unknown key IMPORTANT NOTE
:    [junit4]   2> 403520 WARN  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Expected key, got STRING
:    [junit4]   2> 403520 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection   x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection control_collection
:    [junit4]   2> 403520 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore org.apache.solr.core.MockDirectoryFactory
:    [junit4]   2> 403521 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores/collection1/], dataDir=[null]
:    [junit4]   2> 403521 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c0e52a6
:    [junit4]   2> 403521 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.CachingDirectoryFactory return new directory for /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores/collection1/data
:    [junit4]   2> 403522 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore New index directory detected: old=null new=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores/collection1/data/index/
:    [junit4]   2> 403522 WARN  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Solr index directory '/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores/collection1/data/index' doesn't exist. Creating new index...
:    [junit4]   2> 403522 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.CachingDirectoryFactory return new directory for /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/control-001/cores/collection1/data/index
:    [junit4]   2> 403522 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=41, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
:    [junit4]   2> 403523 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore SolrDeletionPolicy.onCommit: commits: num=1
:    [junit4]   2> 	commit{dir=MockDirectoryWrapper(RAMDirectory@5d3d153a lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@5fcf7f85),segFN=segments_1,generation=1}
:    [junit4]   2> 403523 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore newest commit generation = 1
:    [junit4]   2> 403527 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "nodistrib"
:    [junit4]   2> 403527 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "dedupe"
:    [junit4]   2> 403527 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
:    [junit4]   2> 403527 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "stored_sig"
:    [junit4]   2> 403528 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
:    [junit4]   2> 403528 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
:    [junit4]   2> 403528 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
:    [junit4]   2> 403528 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
:    [junit4]   2> 403528 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore no updateRequestProcessorChain defined as default, creating implicit default
:    [junit4]   2> 403530 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSeconds=60
:    [junit4]   2> 403531 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSeconds=60
:    [junit4]   2> 403532 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSeconds=60
:    [junit4]   2> 403533 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSeconds=60
:    [junit4]   2> 403536 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.RequestHandlers Registered paths: /admin/mbeans,standard,/update/csv,/update/json/docs,/admin/luke,/admin/segments,/get,/admin/system,/replication,/admin/properties,/config,/schema,/admin/plugins,/admin/logging,/update/json,/admin/threads,/admin/ping,/update,/admin/file
:    [junit4]   2> 403536 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore Using default statsCache cache: org.apache.solr.search.stats.LocalStatsCache
:    [junit4]   2> 403537 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
:    [junit4]   2> 403537 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
:    [junit4]   2> 403538 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore Hard AutoCommit: disabled
:    [junit4]   2> 403538 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore Soft AutoCommit: disabled
:    [junit4]   2> 403538 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1596911514, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
:    [junit4]   2> 403589 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore SolrDeletionPolicy.onInit: commits: num=1
:    [junit4]   2> 	commit{dir=MockDirectoryWrapper(RAMDirectory@5d3d153a lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@5fcf7f85),segFN=segments_1,generation=1}
:    [junit4]   2> 403589 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore newest commit generation = 1
:    [junit4]   2> 403589 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening Searcher@449991a3[collection1] main
:    [junit4]   2> 403590 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
:    [junit4]   2> 403591 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
:    [junit4]   2> 403591 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.RestManager Initializing RestManager with initArgs: {}
:    [junit4]   2> 403591 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
:    [junit4]   2> 403591 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage No data found for znode /configs/conf1/_rest_managed.json
:    [junit4]   2> 403592 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
:    [junit4]   2> 403592 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.r.RestManager Initializing 0 registered ManagedResources
:    [junit4]   2> 403592 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for  10000
:    [junit4]   2> 403592 INFO  (searcherExecutor-925-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@449991a3[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
:    [junit4]   2> 403593 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog On first searcher opened, looking up max value of version field
:    [junit4]   2> 403593 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.VersionInfo Refreshing highest value of _version_ for 65536 version buckets from index
:    [junit4]   2> 403593 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.VersionInfo No terms found for _version_, cannot seed version bucket highest value from index
:    [junit4]   2> 403593 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1502493507986653184
:    [junit4]   2> 403595 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.u.UpdateLog Took 2 ms to seed version buckets with highest version 1502493507986653184
:    [junit4]   2> 403595 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController watch zkdir /configs/conf1
:    [junit4]   2> 403596 INFO  (coreLoadExecutor-924-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.CoreContainer registering core: collection1
:    [junit4]   2> 403596 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController Register replica - core:collection1 address:http://127.0.0.1:60774/xk/t collection:control_collection shard:shard1
:    [junit4]   2> 403600 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Running the leader process for shard shard1
:    [junit4]   2> 403602 INFO  (zkCallback-227-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.DistributedQueue NodeChildrenChanged fired on path /overseer/queue state SyncConnected
:    [junit4]   2> 403602 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
:    [junit4]   2> 403602 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
:    [junit4]   2> 403602 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:60774/xk/t/collection1/
:    [junit4]   2> 403602 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
:    [junit4]   2>   "operation":"leader",
:    [junit4]   2>   "shard":"shard1",
:    [junit4]   2>   "collection":"control_collection"} current state version: 1
:    [junit4]   2> 403603 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
:    [junit4]   2> 403603 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:60774/xk/t/collection1/ has no replicas
:    [junit4]   2> 403603 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:60774/xk/t/collection1/ shard1
:    [junit4]   2> 403606 INFO  (zkCallback-227-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.DistributedQueue NodeChildrenChanged fired on path /overseer/queue state SyncConnected
:    [junit4]   2> 403607 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
:    [junit4]   2>   "operation":"leader",
:    [junit4]   2>   "shard":"shard1",
:    [junit4]   2>   "collection":"control_collection",
:    [junit4]   2>   "base_url":"http://127.0.0.1:60774/xk/t",
:    [junit4]   2>   "core":"collection1",
:    [junit4]   2>   "state":"active"} current state version: 1
:    [junit4]   2> 403757 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController We are http://127.0.0.1:60774/xk/t/collection1/ and leader is http://127.0.0.1:60774/xk/t/collection1/
:    [junit4]   2> 403757 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60774/xk/t
:    [junit4]   2> 403757 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
:    [junit4]   2> 403757 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController publishing state=active
:    [junit4]   2> 403757 INFO  (coreZkRegister-918-thread-1-processing-n:127.0.0.1:60774_xk%2Ft x:collection1 s:shard1 c:control_collection r:core_node1) [n:127.0.0.1:60774_xk%2Ft c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController numShards not found on descriptor - reading it from system property
:    [junit4]   2> 403759 INFO  (zkCallback-227-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.DistributedQueue NodeChildrenChanged fired on path /overseer/queue state SyncConnected
:    [junit4]   2> 403760 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
:    [junit4]   2>   "core":"collection1",
:    [junit4]   2>   "core_node_name":"core_node1",
:    [junit4]   2>   "roles":null,
:    [junit4]   2>   "base_url":"http://127.0.0.1:60774/xk/t",
:    [junit4]   2>   "node_name":"127.0.0.1:60774_xk%2Ft",
:    [junit4]   2>   "numShards":"1",
:    [junit4]   2>   "state":"active",
:    [junit4]   2>   "shard":"shard1",
:    [junit4]   2>   "collection":"control_collection",
:    [junit4]   2>   "operation":"state"} current state version: 2
:    [junit4]   2> 403760 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.o.ReplicaMutator Update state numShards=1 message={
:    [junit4]   2>   "core":"collection1",
:    [junit4]   2>   "core_node_name":"core_node1",
:    [junit4]   2>   "roles":null,
:    [junit4]   2>   "base_url":"http://127.0.0.1:60774/xk/t",
:    [junit4]   2>   "node_name":"127.0.0.1:60774_xk%2Ft",
:    [junit4]   2>   "numShards":"1",
:    [junit4]   2>   "state":"active",
:    [junit4]   2>   "shard":"shard1",
:    [junit4]   2>   "collection":"control_collection",
:    [junit4]   2>   "operation":"state"}
:    [junit4]   2> 403876 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.ChaosMonkey monkey: init - expire sessions:false cause connection loss:false
:    [junit4]   2> 404167 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores/collection1
:    [junit4]   2> 404168 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 1 in directory /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001
:    [junit4]   2> 404171 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.e.j.s.Server jetty-9.2.10.v20150310
:    [junit4]   2> 404174 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@28f169fa{/xk/t,null,AVAILABLE}
:    [junit4]   2> 404176 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.e.j.s.ServerConnector Started ServerConnector@2b3b8799{HTTP/1.1}{127.0.0.1:52152}
:    [junit4]   2> 404176 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.e.j.s.Server Started @407672ms
:    [junit4]   2> 404176 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/tempDir-001/jetty1, solrconfig=solrconfig.xml, hostContext=/xk/t, hostPort=52152, coreRootDirectory=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores}
:    [junit4]   2> 404177 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.s.SolrDispatchFilter SolrDispatchFilter.init()sun.misc.Launcher$AppClassLoader@c387f44
:    [junit4]   2> 404177 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.SolrResourceLoader new SolrResourceLoader for directory: '/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/'
:    [junit4]   2> 404192 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/solr.xml
:    [junit4]   2> 404209 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.CoresLocator Config-defined core root directory: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores
:    [junit4]   2> 404209 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.CoreContainer New CoreContainer 1593301048
:    [junit4]   2> 404209 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.CoreContainer Loading cores into CoreContainer [instanceDir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/]
:    [junit4]   2> 404209 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.CoreContainer loading shared library: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/lib
:    [junit4]   2> 404210 WARN  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.SolrResourceLoader Can't find (or read) directory to add to classloader: lib (resolved as: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/lib).
:    [junit4]   2> 404217 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.h.c.HttpShardHandlerFactory created with socketTimeout : 90000,urlScheme : ,connTimeout : 15000,maxConnectionsPerHost : 20,maxConnections : 10000,corePoolSize : 0,maximumPoolSize : 2147483647,maxThreadIdleTime : 5,sizeOfQueue : -1,fairnessPolicy : false,useRetries : false,
:    [junit4]   2> 404218 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
:    [junit4]   2> 404219 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.l.LogWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
:    [junit4]   2> 404219 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.l.LogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
:    [junit4]   2> 404219 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:38050/solr
:    [junit4]   2> 404219 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [    ] o.a.s.c.ZkController zkHost includes chroot
:    [junit4]   2> 405243 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:52152_xk%2Ft    ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52152_xk%2Ft
:    [junit4]   2> 405252 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:52152_xk%2Ft    ] o.a.s.c.Overseer Overseer (id=null) closing
:    [junit4]   2> 405255 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:52152_xk%2Ft    ] o.a.s.c.CoreContainer No authentication plugin used.
:    [junit4]   2> 405255 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:52152_xk%2Ft    ] o.a.s.c.CoreContainer Security conf doesn't exist. Skipping setup for authorization module.
:    [junit4]   2> 405256 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:52152_xk%2Ft    ] o.a.s.c.CoresLocator Looking for core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores
:    [junit4]   2> 405257 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:52152_xk%2Ft    ] o.a.s.c.SolrCore Created CoreDescriptor: {name=collection1, config=solrconfig.xml, transient=false, schema=schema.xml, loadOnStartup=true, instanceDir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores/collection1, collection=collection1, absoluteInstDir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores/collection1/, coreNodeName=, dataDir=data/, shard=
 }
:    [junit4]   2> 405257 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:52152_xk%2Ft    ] o.a.s.c.CoresLocator Found core collection1 in /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores/collection1/
:    [junit4]   2> 405257 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:52152_xk%2Ft    ] o.a.s.c.CoresLocator Found 1 core definitions
:    [junit4]   2> 405258 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.ZkController publishing state=down
:    [junit4]   2> 405258 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.ZkController numShards not found on descriptor - reading it from system property
:    [junit4]   2> 405258 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:52152_xk%2Ft    ] o.a.s.s.SolrDispatchFilter user.dir=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1
:    [junit4]   2> 405259 INFO  (TEST-CollectionsAPIDistributedZkTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:52152_xk%2Ft    ] o.a.s.s.SolrDispatchFilter SolrDispatchFilter.init() done
:    [junit4]   2> 405259 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.ZkController look for our core node name
:    [junit4]   2> 405259 INFO  (zkCallback-227-thread-1-processing-n:127.0.0.1:60774_xk%2Ft) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.DistributedQueue NodeChildrenChanged fired on path /overseer/queue state SyncConnected
:    [junit4]   2> 405260 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.Overseer processMessage: queueSize: 1, message = {
:    [junit4]   2>   "core":"collection1",
:    [junit4]   2>   "roles":null,
:    [junit4]   2>   "base_url":"http://127.0.0.1:52152/xk/t",
:    [junit4]   2>   "node_name":"127.0.0.1:52152_xk%2Ft",
:    [junit4]   2>   "numShards":"2",
:    [junit4]   2>   "state":"down",
:    [junit4]   2>   "shard":null,
:    [junit4]   2>   "collection":"collection1",
:    [junit4]   2>   "operation":"state"} current state version: 3
:    [junit4]   2> 405261 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.o.ReplicaMutator Update state numShards=2 message={
:    [junit4]   2>   "core":"collection1",
:    [junit4]   2>   "roles":null,
:    [junit4]   2>   "base_url":"http://127.0.0.1:52152/xk/t",
:    [junit4]   2>   "node_name":"127.0.0.1:52152_xk%2Ft",
:    [junit4]   2>   "numShards":"2",
:    [junit4]   2>   "state":"down",
:    [junit4]   2>   "shard":null,
:    [junit4]   2>   "collection":"collection1",
:    [junit4]   2>   "operation":"state"}
:    [junit4]   2> 405261 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.o.ClusterStateMutator building a new cName: collection1
:    [junit4]   2> 405261 INFO  (OverseerStateUpdate-93905844134674435-127.0.0.1:60774_xk%2Ft-n_0000000000) [n:127.0.0.1:60774_xk%2Ft    ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
:    [junit4]   2> 406260 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.ZkController waiting to find shard id in clusterstate for collection1
:    [junit4]   2> 406261 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.ZkController Check for collection zkNode:collection1
:    [junit4]   2> 406262 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.ZkController Collection zkNode exists
:    [junit4]   2> 406266 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.SolrResourceLoader new SolrResourceLoader for directory: '/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores/collection1/'
:    [junit4]   2> 406284 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.Config loaded config solrconfig.xml with version 0 
:    [junit4]   2> 406293 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.SolrConfig current version of requestparams : -1
:    [junit4]   2> 406296 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.0.0
:    [junit4]   2> 406305 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.Config Loaded SolrConfig: solrconfig.xml
:    [junit4]   2> 406306 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.IndexSchema Reading Solr Schema from /configs/conf1/schema.xml
:    [junit4]   2> 406311 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
:    [junit4]   2> 406415 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
:    [junit4]   2> 406422 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.IndexSchema default search field in schema is text
:    [junit4]   2> 406423 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.IndexSchema unique key field: id
:    [junit4]   2> 406434 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.FileExchangeRateProvider Reloading exchange rates from file currency.xml
:    [junit4]   2> 406443 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.FileExchangeRateProvider Reloading exchange rates from file currency.xml
:    [junit4]   2> 406448 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Reloading exchange rates from open-exchange-rates.json
:    [junit4]   2> 406454 WARN  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Unknown key IMPORTANT NOTE
:    [junit4]   2> 406455 WARN  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Expected key, got STRING
:    [junit4]   2> 406455 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Reloading exchange rates from open-exchange-rates.json
:    [junit4]   2> 406457 WARN  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Unknown key IMPORTANT NOTE
:    [junit4]   2> 406459 WARN  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.s.OpenExchangeRatesOrgProvider Expected key, got STRING
:    [junit4]   2> 406459 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1   x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1
:    [junit4]   2> 406459 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore org.apache.solr.core.MockDirectoryFactory
:    [junit4]   2> 406462 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores/collection1/], dataDir=[null]
:    [junit4]   2> 406463 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c0e52a6
:    [junit4]   2> 406464 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.CachingDirectoryFactory return new directory for /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores/collection1/data
:    [junit4]   2> 406467 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore New index directory detected: old=null new=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores/collection1/data/index/
:    [junit4]   2> 406467 WARN  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Solr index directory '/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores/collection1/data/index' doesn't exist. Creating new index...
:    [junit4]   2> 406467 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.CachingDirectoryFactory return new directory for /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/../../../../../../../../../../x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J1/temp/solr.cloud.CollectionsAPIDistributedZkTest 3AF6852C6379681-001/shard-1-001/cores/collection1/data/index
:    [junit4]   2> 406468 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=41, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
:    [junit4]   2> 406472 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore SolrDeletionPolicy.onCommit: commits: num=1
:    [junit4]   2> 	commit{dir=MockDirectoryWrapper(RAMDirectory@564eed24 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@28bbdc9b),segFN=segments_1,generation=1}
:    [junit4]   2> 406472 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore newest commit generation = 1
:    [junit4]   2> 406502 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "nodistrib"
:    [junit4]   2> 406502 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "dedupe"
:    [junit4]   2> 406502 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
:    [junit4]   2> 406502 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "stored_sig"
:    [junit4]   2> 406502 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
:    [junit4]   2> 406503 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "distrib-dup-test-chain-explicit"
:    [junit4]   2> 406503 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain creating updateRequestProcessorChain "distrib-dup-test-chain-implicit"
:    [junit4]   2> 406503 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.p.UpdateRequestProcessorChain inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
:    [junit4]   2> 406503 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore no updateRequestProcessorChain defined as default, creating implicit default
:    [junit4]   2> 406505 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSeconds=60
:    [junit4]   2> 406506 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSeconds=60
:    [junit4]   2> 406507 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSeconds=60
:    [junit4]   2> 406508 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.h.l.XMLLoader xsltCacheLifetimeSeconds=60
:    [junit4]   2> 406518 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.RequestHandlers Registered paths: /admin/mbeans,standard,/update/csv,/update/json/docs,/admin/luke,/admin/segments,/get,/admin/system,/replication,/admin/properties,/config,/schema,/admin/plugins,/admin/logging,/update/json,/admin/threads,/admin/ping,/update,/admin/file
:    [junit4]   2> 406518 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore Using default statsCache cache: org.apache.solr.search.stats.LocalStatsCache
:    [junit4]   2> 406519 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
:    [junit4]   2> 406519 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
:    [junit4]   2> 406520 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore Hard AutoCommit: disabled
:    [junit4]   2> 406520 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore Soft AutoCommit: disabled
:    [junit4]   2> 406521 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1596911514, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
:    [junit4]   2> 406572 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore SolrDeletionPolicy.onInit: commits: num=1
:    [junit4]   2> 	commit{dir=MockDirectoryWrapper(RAMDirectory@564eed24 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@28bbdc9b),segFN=segments_1,generation=1}
:    [junit4]   2> 406572 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore newest commit generation = 1
:    [junit4]   2> 406573 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.s.SolrIndexSearcher Opening Searcher@4a9cfa4a[collection1] main
:    [junit4]   2> 406573 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
:    [junit4]   2> 406574 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
:    [junit4]   2> 406574 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.RestManager Initializing RestManager with initArgs: {}
:    [junit4]   2> 406574 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
:    [junit4]   2> 406574 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage No data found for znode /configs/conf1/_rest_managed.json
:    [junit4]   2> 406574 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
:    [junit4]   2> 406575 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.r.RestManager Initializing 0 registered ManagedResources
:    [junit4]   2> 406575 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for  10000
:    [junit4]   2> 406576 INFO  (searcherExecutor-936-thread-1-processing-n:127.0.0.1:52152_xk%2Ft x:collection1 s:shard2 c:collection1 r:core_node1) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@4a9cfa4a[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
:    [junit4]   2> 406576 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateLog On first searcher opened, looking up max value of version field
:    [junit4]   2> 406576 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.VersionInfo Refreshing highest value of _version_ for 65536 version buckets from index
:    [junit4]   2> 406576 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.VersionInfo No terms found for _version_, cannot seed version bucket highest value from index
:    [junit4]   2> 406576 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1502493511114555392
:    [junit4]   2> 406578 INFO  (coreLoadExecutor-935-thread-1-processing-n:127.0.0.1:52152_xk%2Ft) [n:127.0.0.1:52152_xk%2Ft c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.UpdateLog Took 2 ms to seed version buckets with highest version 1502493511114555392
:    [junit4]
: 
: [...truncated too long message...]
: 
: e_node3 x:collection1] o.a.s.c.SocketProxy Closing 13 connections to: http://127.0.0.1:58289/pn_rez/m, target: http://127.0.0.1:34763/pn_rez/m
:    [junit4]   2> 2318424 WARN  (TEST-HttpPartitionTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:39551_pn_rez%2Fm c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.SocketProxy Closing 7 connections to: http://127.0.0.1:39551/pn_rez/m, target: http://127.0.0.1:46711/pn_rez/m
:    [junit4]   2> 2318424 WARN  (TEST-HttpPartitionTest.test-seed#[3AF6852C6379681]) [n:127.0.0.1:39551_pn_rez%2Fm c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.SocketProxy Closing 5 connections to: http://127.0.0.1:44114/pn_rez/m, target: http://127.0.0.1:41855/pn_rez/m
:    [junit4]   2> 2318425 INFO  (SUITE-HttpPartitionTest-seed#[3AF6852C6379681]-worker) [n:127.0.0.1:39551_pn_rez%2Fm c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.SolrTestCaseJ4 ###deleteCore
:    [junit4]   2> NOTE: test params are: codec=FastDecompressionCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST_DECOMPRESSION, chunkSize=5063, maxDocsPerChunk=251, blockSize=4), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST_DECOMPRESSION, chunkSize=5063, blockSize=4)), sim=DefaultSimilarity, locale=en_AU, timezone=America/Recife
:    [junit4]   2> NOTE: Linux 3.13.0-52-generic amd64/Oracle Corporation 1.8.0_25 (64-bit)/cpus=4,threads=1,free=246850776,total=528482304
:    [junit4]   2> NOTE: All tests run in this JVM: [TestCopyFieldCollectionResource, LeaderElectionIntegrationTest, ActionThrottleTest, TestLazyCores, TestCloudInspectUtil, HighlighterTest, TestImplicitCoreProperties, MultiTermTest, SuggesterWFSTTest, TestObjectReleaseTracker, CSVRequestHandlerTest, TestDFRSimilarityFactory, DistributedSpellCheckComponentTest, TestSolrXml, TestUpdate, TestReqParamsAPI, TestOrdValues, TestCursorMarkWithoutUniqueKey, FastVectorHighlighterTest, MergeStrategyTest, TestFieldSortValues, UUIDFieldTest, TermsComponentTest, TestFunctionQuery, TestArbitraryIndexDir, DebugComponentTest, DateRangeFieldTest, SolrIndexConfigTest, VMParamsZkACLAndCredentialsProvidersTest, IndexBasedSpellCheckerTest, MinimalSchemaTest, TestBadConfig, AliasIntegrationTest, TestInitParams, TestNoOpRegenerator, CursorPagingTest, BlockCacheTest, SSLMigrationTest, TestStandardQParsers, DefaultValueUpdateProcessorTest, TestDistributedMissingSort, TestDistributedStatsComponentCardinality,
  TestCSVLoader, TestHighlightDedupGrouping, TestJmxIntegration, SolrCoreTest, TestBinaryField, SimplePostToolTest, HdfsWriteToMultipleCollectionsTest, HdfsRecoverLeaseTest, ClusterStateTest, TestConfig, TestSolr4Spatial2, TestCodecSupport, AnalysisErrorHandlingTest, TermVectorComponentTest, HighlighterConfigTest, CdcrUpdateLogTest, TestRandomFaceting, SimpleMLTQParserTest, SpatialHeatmapFacetsTest, TestStressLucene, TestFaceting, TestIBSimilarityFactory, TestIntervalFaceting, CurrencyFieldXmlFileTest, TestMiniSolrCloudClusterSSL, TestWordDelimiterFilterFactory, TestBlendedInfixSuggestions, TestTrackingShardHandlerFactory, TestQuerySenderListener, RequestHandlersTest, QueryElevationComponentTest, TestSolrConfigHandler, TestJmxMonitoredMap, TestPostingsSolrHighlighter, IndexSchemaTest, TestMissingGroups, TestSolrIndexConfig, TestSolr4Spatial, BasicDistributedZkTest, BasicDistributedZk2Test, UnloadDistributedZkTest, SyncSliceTest, BasicZkTest, RecoveryZkTest, TestReplicationHandler, Te
 stMergePolicyConfig, SampleTest, NumericFieldsTest, TestElisionMultitermQuery, DirectSolrConnectionTest, TestPhraseSuggestions, TestSweetSpotSimilarityFactory, TestLMJelinekMercerSimilarityFactory, TestFastOutputStream, OpenExchangeRatesOrgProviderTest, URLClassifyProcessorTest, PluginInfoTest, TestFastLRUCache, DateMathParserTest, PrimUtilsTest, TestSuggestSpellingConverter, DateFieldTest, SpellingQueryConverterTest, DOMUtilTest, TestLRUCache, TestUtils, TestDocumentBuilder, ZkNodePropsTest, SliceStateTest, FileUtilsTest, CircularListTest, DistributedIntervalFacetingTest, CollectionStateFormat2Test, DeleteInactiveReplicaTest, DeleteShardTest, DistribJoinFromCollectionTest, HttpPartitionTest]
:    [junit4]   2> NOTE: download the large Jenkins line-docs file by running 'ant get-jenkins-line-docs' in the lucene directory.
:    [junit4]   2> NOTE: reproduce with: ant test  -Dtestcase=HttpPartitionTest -Dtests.seed=3AF6852C6379681 -Dtests.multiplier=2 -Dtests.nightly=true -Dtests.slow=true -Dtests.linedocsfile=/x1/jenkins/lucene-data/enwiki.random.lines.txt -Dtests.locale=en_AU -Dtests.timezone=America/Recife -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
:    [junit4] ERROR   0.00s J0 | HttpPartitionTest (suite) <<<
:    [junit4]    > Throwable #1: java.lang.RuntimeException: file handle leaks: [SeekableByteChannel(/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build/solr-core/test/J0/temp/solr.cloud.HttpPartitionTest 3AF6852C6379681-001/index-SimpleFSDirectory-011/segments_2)]
:    [junit4]    > 	at __randomizedtesting.SeedInfo.seed([3AF6852C6379681]:0)
:    [junit4]    > 	at org.apache.lucene.mockfile.LeakFS.onClose(LeakFS.java:64)
:    [junit4]    > 	at org.apache.lucene.mockfile.FilterFileSystem.close(FilterFileSystem.java:78)
:    [junit4]    > 	at org.apache.lucene.mockfile.FilterFileSystem.close(FilterFileSystem.java:79)
:    [junit4]    > 	at java.lang.Thread.run(Thread.java:745)
:    [junit4]    > Caused by: java.lang.Exception
:    [junit4]    > 	at org.apache.lucene.mockfile.LeakFS.onOpen(LeakFS.java:47)
:    [junit4]    > 	at org.apache.lucene.mockfile.HandleTrackingFS.callOpenHook(HandleTrackingFS.java:82)
:    [junit4]    > 	at org.apache.lucene.mockfile.HandleTrackingFS.newByteChannel(HandleTrackingFS.java:272)
:    [junit4]    > 	at org.apache.lucene.mockfile.FilterFileSystemProvider.newByteChannel(FilterFileSystemProvider.java:213)
:    [junit4]    > 	at org.apache.lucene.mockfile.HandleTrackingFS.newByteChannel(HandleTrackingFS.java:241)
:    [junit4]    > 	at java.nio.file.Files.newByteChannel(Files.java:361)
:    [junit4]    > 	at java.nio.file.Files.newByteChannel(Files.java:407)
:    [junit4]    > 	at org.apache.lucene.store.SimpleFSDirectory.openInput(SimpleFSDirectory.java:76)
:    [junit4]    > 	at org.apache.lucene.store.Directory.openChecksumInput(Directory.java:110)
:    [junit4]    > 	at org.apache.lucene.store.RawDirectoryWrapper.openChecksumInput(RawDirectoryWrapper.java:42)
:    [junit4]    > 	at org.apache.lucene.index.SegmentInfos.readCommit(SegmentInfos.java:269)
:    [junit4]    > 	at org.apache.lucene.index.CheckIndex.checkIndex(CheckIndex.java:488)
:    [junit4]    > 	at org.apache.lucene.util.TestUtil.checkIndex(TestUtil.java:278)
:    [junit4]    > 	at org.apache.lucene.util.TestUtil.checkIndex(TestUtil.java:265)
:    [junit4]    > 	at org.apache.lucene.store.BaseDirectoryWrapper.close(BaseDirectoryWrapper.java:46)
:    [junit4]    > 	at org.apache.solr.core.CachingDirectoryFactory.close(CachingDirectoryFactory.java:307)
:    [junit4]    > 	at org.apache.solr.core.CachingDirectoryFactory.closeCacheValue(CachingDirectoryFactory.java:273)
:    [junit4]    > 	at org.apache.solr.core.CachingDirectoryFactory.close(CachingDirectoryFactory.java:203)
:    [junit4]    > 	at org.apache.solr.core.SolrCore.close(SolrCore.java:1254)
:    [junit4]    > 	at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:311)
:    [junit4]    > 	at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:198)
:    [junit4]    > 	at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:159)
:    [junit4]    > 	at org.apache.solr.cloud.LeaderElector.joinElection(LeaderElector.java:348)
:    [junit4]    > 	at org.apache.solr.cloud.ZkController.joinElection(ZkController.java:1070)
:    [junit4]    > 	at org.apache.solr.cloud.ZkController.register(ZkController.java:884)
:    [junit4]    > 	at org.apache.solr.cloud.ZkController$RegisterCoreAsync.call(ZkController.java:225)
:    [junit4]    > 	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
:    [junit4]    > 	at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor$1.run(ExecutorUtil.java:156)
:    [junit4]    > 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
:    [junit4]    > 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
:    [junit4]    > 	... 1 more
:    [junit4] Completed [404/503] on J0 in 143.50s, 1 test, 1 error <<< FAILURES!
: 
: [...truncated 337 lines...]
: BUILD FAILED
: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:533: The following error occurred while executing this line:
: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:474: The following error occurred while executing this line:
: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/build.xml:61: The following error occurred while executing this line:
: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/extra-targets.xml:39: The following error occurred while executing this line:
: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/build.xml:230: The following error occurred while executing this line:
: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/solr/common-build.xml:512: The following error occurred while executing this line:
: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:1415: The following error occurred while executing this line:
: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-NightlyTests-trunk/lucene/common-build.xml:973: There were test failures: 503 suites, 1986 tests, 1 suite-level error, 1 error, 1 failure, 20 ignored (10 assumptions)
: 
: Total time: 148 minutes 7 seconds
: Build step 'Invoke Ant' marked build as failure
: Archiving artifacts
: No artifacts from Lucene-Solr-NightlyTests-trunk #679 to compare, so performing full copy of artifacts
: Recording test results
: Email was triggered for: Failure
: Sending email for trigger: Failure
: 
: 
: 

-Hoss
http://www.lucidworks.com/

Mime
View raw message