You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2017/05/08 18:06:44 UTC
[JENKINS-EA] Lucene-Solr-6.x-Linux (32bit/jdk-9-ea+168) - Build #
3469 - Still Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Linux/3469/
Java: 32bit/jdk-9-ea+168 -server -XX:+UseSerialGC
1 tests failed.
FAILED: org.apache.solr.cloud.ShardSplitTest.testSplitWithChaosMonkey
Error Message:
There are still nodes recoverying - waited for 330 seconds
Stack Trace:
java.lang.AssertionError: There are still nodes recoverying - waited for 330 seconds
at __randomizedtesting.SeedInfo.seed([A77CD4947DE33092:2C5B07453CE59B16]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:187)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:144)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:139)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.waitForRecoveriesToFinish(AbstractFullDistribZkTestBase.java:856)
at org.apache.solr.cloud.ShardSplitTest.testSplitWithChaosMonkey(ShardSplitTest.java:437)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:563)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:992)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:967)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
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:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
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:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.base/java.lang.Thread.run(Thread.java:844)
Build Log:
[...truncated 12346 lines...]
[junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/init-core-data-001
[junit4] 2> 525669 INFO (SUITE-ShardSplitTest-seed#[A77CD4947DE33092]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields
[junit4] 2> 525670 INFO (SUITE-ShardSplitTest-seed#[A77CD4947DE33092]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl="https://issues.apache.org/jira/browse/SOLR-5776")
[junit4] 2> 525670 INFO (SUITE-ShardSplitTest-seed#[A77CD4947DE33092]-worker) [ ] o.a.s.BaseDistributedSearchTestCase Setting hostContext system property: /
[junit4] 2> 525671 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 525671 INFO (Thread-1296) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 525671 INFO (Thread-1296) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 525673 ERROR (Thread-1296) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 525771 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkTestServer start zk server on port:42618
[junit4] 2> 525779 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 525780 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4] 2> 525781 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 525782 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 525783 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 525784 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 525784 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
[junit4] 2> 525785 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 525786 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 525787 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 525790 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 525906 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/control-001/cores/collection1
[junit4] 2> 525907 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 525909 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@16de0ea{/,null,AVAILABLE}
[junit4] 2> 525909 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1595188{HTTP/1.1,[http/1.1]}{127.0.0.1:42905}
[junit4] 2> 525909 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.Server Started @527933ms
[junit4] 2> 525910 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/, solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/tempDir-001/control/data, hostPort=42905, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/control-001/cores}
[junit4] 2> 525910 ERROR (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 525910 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.0
[junit4] 2> 525910 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 525910 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 525910 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-05-08T17:34:03.278871Z
[junit4] 2> 525913 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 525913 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/control-001/solr.xml
[junit4] 2> 525918 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 525919 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:42618/solr
[junit4] 2> 525931 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 525933 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:42905_
[junit4] 2> 525933 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.Overseer Overseer (id=97928140753469444-127.0.0.1:42905_-n_0000000000) starting
[junit4] 2> 525938 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42905_
[junit4] 2> 525940 INFO (zkCallback-1711-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 526091 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/control-001/cores
[junit4] 2> 526091 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 526092 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 526094 INFO (OverseerStateUpdate-97928140753469444-127.0.0.1:42905_-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 527102 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.0
[junit4] 2> 527113 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 527198 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 527211 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection control_collection, trusted=true
[junit4] 2> 527211 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 527211 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/control-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/control-001/cores/collection1/data/]
[junit4] 2> 527211 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@f369ea
[junit4] 2> 527214 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=20, maxMergedSegmentMB=46.6533203125, floorSegmentMB=0.9384765625, forceMergeDeletesPctAllowed=6.519256676813555, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 527237 WARN (coreLoadExecutor-3323-thread-1) [ ] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 527267 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 527267 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 527268 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 527268 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 527269 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=36, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=2.076171875, noCFSRatio=0.0]
[junit4] 2> 527269 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@d8699a[collection1] main]
[junit4] 2> 527270 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 527270 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 527270 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 527271 INFO (searcherExecutor-3324-thread-1) [ ] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@d8699a[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 527272 INFO (coreLoadExecutor-3323-thread-1) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1566850253733232640
[junit4] 2> 527277 INFO (coreZkRegister-3316-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 527277 INFO (coreZkRegister-3316-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 527277 INFO (coreZkRegister-3316-thread-1) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:42905/collection1/
[junit4] 2> 527277 INFO (coreZkRegister-3316-thread-1) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 527277 INFO (coreZkRegister-3316-thread-1) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:42905/collection1/ has no replicas
[junit4] 2> 527277 INFO (coreZkRegister-3316-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 527279 INFO (coreZkRegister-3316-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:42905/collection1/ shard1
[junit4] 2> 527430 INFO (coreZkRegister-3316-thread-1) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 527598 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 527599 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:42618/solr ready
[junit4] 2> 527599 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ChaosMonkey monkey: init - expire sessions:false cause connection loss:false
[junit4] 2> 527745 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-1-001/cores/collection1
[junit4] 2> 527746 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 1 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-1-001
[junit4] 2> 527746 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 527747 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@7e684a{/,null,AVAILABLE}
[junit4] 2> 527748 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@260661{HTTP/1.1,[http/1.1]}{127.0.0.1:37824}
[junit4] 2> 527748 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.Server Started @529771ms
[junit4] 2> 527748 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/, solrconfig=solrconfig.xml, solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/tempDir-001/jetty1, hostPort=37824, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-1-001/cores}
[junit4] 2> 527749 ERROR (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 527749 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.0
[junit4] 2> 527749 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 527749 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 527749 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-05-08T17:34:05.117525Z
[junit4] 2> 527752 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 527752 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-1-001/solr.xml
[junit4] 2> 527756 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 527757 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:42618/solr
[junit4] 2> 527762 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 527763 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 527764 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37824_
[junit4] 2> 527765 INFO (zkCallback-1711-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 527765 INFO (zkCallback-1720-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 527765 INFO (zkCallback-1715-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 527903 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-1-001/cores
[junit4] 2> 527903 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 527904 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 527905 INFO (OverseerStateUpdate-97928140753469444-127.0.0.1:42905_-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 528913 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.0
[junit4] 2> 528923 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 529018 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 529027 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1, trusted=true
[junit4] 2> 529028 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 529028 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-1-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-1-001/cores/collection1/data/]
[junit4] 2> 529028 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@f369ea
[junit4] 2> 529030 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=20, maxMergedSegmentMB=46.6533203125, floorSegmentMB=0.9384765625, forceMergeDeletesPctAllowed=6.519256676813555, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 529083 WARN (coreLoadExecutor-3334-thread-1) [ ] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 529131 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 529131 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 529133 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 529133 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 529134 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=36, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=2.076171875, noCFSRatio=0.0]
[junit4] 2> 529134 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@81807f[collection1] main]
[junit4] 2> 529135 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 529135 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 529135 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 529137 INFO (searcherExecutor-3335-thread-1) [ ] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@81807f[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 529137 INFO (coreLoadExecutor-3334-thread-1) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1566850255688826880
[junit4] 2> 529142 INFO (coreZkRegister-3329-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 529142 INFO (coreZkRegister-3329-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 529142 INFO (coreZkRegister-3329-thread-1) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:37824/collection1/
[junit4] 2> 529142 INFO (coreZkRegister-3329-thread-1) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 529142 INFO (coreZkRegister-3329-thread-1) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:37824/collection1/ has no replicas
[junit4] 2> 529142 INFO (coreZkRegister-3329-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 529144 INFO (coreZkRegister-3329-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:37824/collection1/ shard2
[junit4] 2> 529294 INFO (coreZkRegister-3329-thread-1) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 529548 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-2-001/cores/collection1
[junit4] 2> 529548 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 2 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-2-001
[junit4] 2> 529549 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 529566 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1fea56d{/,null,AVAILABLE}
[junit4] 2> 529567 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1e12703{HTTP/1.1,[http/1.1]}{127.0.0.1:43223}
[junit4] 2> 529567 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.Server Started @531590ms
[junit4] 2> 529567 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/, solrconfig=solrconfig.xml, solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/tempDir-001/jetty2, hostPort=43223, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-2-001/cores}
[junit4] 2> 529568 ERROR (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 529568 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.0
[junit4] 2> 529568 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 529568 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 529568 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-05-08T17:34:06.936803Z
[junit4] 2> 529570 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 529571 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-2-001/solr.xml
[junit4] 2> 529576 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 529577 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:42618/solr
[junit4] 2> 529583 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 529584 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 529585 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43223_
[junit4] 2> 529585 INFO (zkCallback-1715-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 529585 INFO (zkCallback-1720-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 529585 INFO (zkCallback-1726-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 529586 INFO (zkCallback-1711-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 529684 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-2-001/cores
[junit4] 2> 529684 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 529685 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 529685 INFO (OverseerStateUpdate-97928140753469444-127.0.0.1:42905_-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 530692 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.0
[junit4] 2> 530707 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 530796 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 530804 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1, trusted=true
[junit4] 2> 530804 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 530804 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-2-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-2-001/cores/collection1/data/]
[junit4] 2> 530805 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@f369ea
[junit4] 2> 530806 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=20, maxMergedSegmentMB=46.6533203125, floorSegmentMB=0.9384765625, forceMergeDeletesPctAllowed=6.519256676813555, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 530839 WARN (coreLoadExecutor-3345-thread-1) [ ] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 530872 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 530872 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 530872 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 530872 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 530873 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=36, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=2.076171875, noCFSRatio=0.0]
[junit4] 2> 530874 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@54ec2[collection1] main]
[junit4] 2> 530874 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 530874 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 530875 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 530875 INFO (searcherExecutor-3346-thread-1) [ ] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@54ec2[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 530876 INFO (coreLoadExecutor-3345-thread-1) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1566850257512300544
[junit4] 2> 530880 INFO (coreZkRegister-3340-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 530880 INFO (coreZkRegister-3340-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 530880 INFO (coreZkRegister-3340-thread-1) [ ] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:43223/collection1/
[junit4] 2> 530880 INFO (coreZkRegister-3340-thread-1) [ ] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 530880 INFO (coreZkRegister-3340-thread-1) [ ] o.a.s.c.SyncStrategy http://127.0.0.1:43223/collection1/ has no replicas
[junit4] 2> 530880 INFO (coreZkRegister-3340-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 530882 INFO (coreZkRegister-3340-thread-1) [ ] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:43223/collection1/ shard1
[junit4] 2> 531033 INFO (coreZkRegister-3340-thread-1) [ ] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 531306 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-3-001/cores/collection1
[junit4] 2> 531306 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 3 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-3-001
[junit4] 2> 531306 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 531307 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1039035{/,null,AVAILABLE}
[junit4] 2> 531307 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@14e0fe{HTTP/1.1,[http/1.1]}{127.0.0.1:38218}
[junit4] 2> 531309 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.Server Started @533332ms
[junit4] 2> 531309 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/, solrconfig=solrconfig.xml, solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/tempDir-001/jetty3, hostPort=38218, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-3-001/cores}
[junit4] 2> 531309 ERROR (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 531309 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.0
[junit4] 2> 531309 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 531309 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 531309 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-05-08T17:34:08.677913Z
[junit4] 2> 531311 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 531311 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-3-001/solr.xml
[junit4] 2> 531315 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 531316 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:42618/solr
[junit4] 2> 531323 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3)
[junit4] 2> 531324 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 531344 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38218_
[junit4] 2> 531345 INFO (zkCallback-1726-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 531345 INFO (zkCallback-1720-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 531345 INFO (zkCallback-1711-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 531348 INFO (zkCallback-1715-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 531348 INFO (zkCallback-1732-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 531466 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-3-001/cores
[junit4] 2> 531466 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 531466 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 531467 INFO (OverseerStateUpdate-97928140753469444-127.0.0.1:42905_-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 532478 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.0
[junit4] 2> 532493 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 532580 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 532589 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1, trusted=true
[junit4] 2> 532589 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 532589 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-3-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-3-001/cores/collection1/data/]
[junit4] 2> 532590 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@f369ea
[junit4] 2> 532593 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=20, maxMergedSegmentMB=46.6533203125, floorSegmentMB=0.9384765625, forceMergeDeletesPctAllowed=6.519256676813555, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 532607 WARN (coreLoadExecutor-3356-thread-1) [ ] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 532653 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 532653 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 532654 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 532654 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 532655 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=36, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=2.076171875, noCFSRatio=0.0]
[junit4] 2> 532655 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@10d92f0[collection1] main]
[junit4] 2> 532656 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 532656 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 532656 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 532657 INFO (searcherExecutor-3357-thread-1) [ ] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@10d92f0[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 532657 INFO (coreLoadExecutor-3356-thread-1) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1566850259379814400
[junit4] 2> 532660 INFO (coreZkRegister-3351-thread-1) [ ] o.a.s.c.ZkController Core needs to recover:collection1
[junit4] 2> 532661 INFO (updateExecutor-1729-thread-1) [ ] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 532661 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 532661 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 532661 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[collection1]
[junit4] 2> 532661 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 532661 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.c.RecoveryStrategy Publishing state of core [collection1] as recovering, leader is [http://127.0.0.1:37824/collection1/] and I am [http://127.0.0.1:38218/collection1/]
[junit4] 2> 532662 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:37824]; [WaitForState: action=PREPRECOVERY&core=collection1&nodeName=127.0.0.1:38218_&coreNodeName=core_node3&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 532665 INFO (qtp21118466-6941) [ ] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true
[junit4] 2> 532666 INFO (qtp21118466-6941) [ ] o.a.s.h.a.PrepRecoveryOp Will wait a max of 183 seconds to see collection1 (shard2 of collection1) have state: recovering
[junit4] 2> 532666 INFO (qtp21118466-6941) [ ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard2, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:38218_, coreNodeName=core_node3, onlyIfActiveCheckResult=false, nodeProps: core_node3:{"core":"collection1","base_url":"http://127.0.0.1:38218","node_name":"127.0.0.1:38218_","state":"down"}
[junit4] 2> 533097 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-4-001/cores/collection1
[junit4] 2> 533097 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 4 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-4-001
[junit4] 2> 533099 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 533099 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2c9f99{/,null,AVAILABLE}
[junit4] 2> 533100 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1b691df{HTTP/1.1,[http/1.1]}{127.0.0.1:45448}
[junit4] 2> 533100 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.e.j.s.Server Started @535123ms
[junit4] 2> 533100 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/, solrconfig=solrconfig.xml, solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/tempDir-001/jetty4, hostPort=45448, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-4-001/cores}
[junit4] 2> 533100 ERROR (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 533100 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.0
[junit4] 2> 533100 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 533100 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 533100 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-05-08T17:34:10.468915Z
[junit4] 2> 533102 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 533102 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-4-001/solr.xml
[junit4] 2> 533106 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 533107 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:42618/solr
[junit4] 2> 533113 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 533114 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 533115 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45448_
[junit4] 2> 533116 INFO (zkCallback-1726-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 533116 INFO (zkCallback-1720-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 533116 INFO (zkCallback-1715-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 533116 INFO (zkCallback-1711-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 533116 INFO (zkCallback-1739-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 533117 INFO (zkCallback-1732-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 533281 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-4-001/cores
[junit4] 2> 533281 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 533281 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 533282 INFO (OverseerStateUpdate-97928140753469444-127.0.0.1:42905_-n_0000000000) [ ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 533666 INFO (qtp21118466-6941) [ ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard2, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=recovering, localState=active, nodeName=127.0.0.1:38218_, coreNodeName=core_node3, onlyIfActiveCheckResult=false, nodeProps: core_node3:{"core":"collection1","base_url":"http://127.0.0.1:38218","node_name":"127.0.0.1:38218_","state":"recovering"}
[junit4] 2> 533666 INFO (qtp21118466-6941) [ ] o.a.s.h.a.PrepRecoveryOp Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4] 2> 533666 INFO (qtp21118466-6941) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:38218_&onlyIfLeaderActive=true&core=collection1&coreNodeName=core_node3&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=1000
[junit4] 2> 534166 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.c.RecoveryStrategy Attempting to PeerSync from [http://127.0.0.1:37824/collection1/] - recoveringAfterStartup=[true]
[junit4] 2> 534167 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.u.PeerSync PeerSync: core=collection1 url=http://127.0.0.1:38218 START replicas=[http://127.0.0.1:37824/collection1/] nUpdates=100
[junit4] 2> 534169 INFO (qtp21118466-6941) [ ] o.a.s.u.IndexFingerprint IndexFingerprint millis:0.0 result:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=0, maxInHash=0, versionsHash=0, numVersions=0, numDocs=0, maxDoc=0}
[junit4] 2> 534169 INFO (qtp21118466-6941) [ ] o.a.s.c.S.Request [collection1] webapp= path=/get params={distrib=false&qt=/get&getFingerprint=9223372036854775807&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 534170 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.u.IndexFingerprint IndexFingerprint millis:0.0 result:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=0, maxInHash=0, versionsHash=0, numVersions=0, numDocs=0, maxDoc=0}
[junit4] 2> 534170 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.u.PeerSync We are already in sync. No need to do a PeerSync
[junit4] 2> 534170 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 534170 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 534170 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 534170 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.c.RecoveryStrategy PeerSync stage of recovery was successful.
[junit4] 2> 534170 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.c.RecoveryStrategy Replaying updates buffered during PeerSync.
[junit4] 2> 534170 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.c.RecoveryStrategy No replay needed.
[junit4] 2> 534170 INFO (recoveryExecutor-1730-thread-1) [ ] o.a.s.c.RecoveryStrategy Registering as Active after recovery.
[junit4] 2> 534294 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.0
[junit4] 2> 534309 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 534424 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 534438 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1, trusted=true
[junit4] 2> 534439 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 534439 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-4-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001/shard-4-001/cores/collection1/data/]
[junit4] 2> 534439 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@f369ea
[junit4] 2> 534442 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=20, maxMergedSegmentMB=46.6533203125, floorSegmentMB=0.9384765625, forceMergeDeletesPctAllowed=6.519256676813555, segmentsPerTier=43.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 534472 WARN (coreLoadExecutor-3367-thread-1) [ ] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 534532 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 534532 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 534533 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 534533 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 534534 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=36, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=2.076171875, noCFSRatio=0.0]
[junit4] 2> 534534 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.s.SolrIndexSearcher Opening [Searcher@dd93c1[collection1] main]
[junit4] 2> 534535 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 534535 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 534535 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 534536 INFO (searcherExecutor-3368-thread-1) [ ] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@dd93c1[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 534537 INFO (coreLoadExecutor-3367-thread-1) [ ] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1566850261351137280
[junit4] 2> 534540 INFO (coreZkRegister-3362-thread-1) [ ] o.a.s.c.ZkController Core needs to recover:collection1
[junit4] 2> 534540 INFO (updateExecutor-1736-thread-1) [ ] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 534540 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 534541 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 534541 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[collection1]
[junit4] 2> 534541 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 534541 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.c.RecoveryStrategy Publishing state of core [collection1] as recovering, leader is [http://127.0.0.1:43223/collection1/] and I am [http://127.0.0.1:45448/collection1/]
[junit4] 2> 534542 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:43223]; [WaitForState: action=PREPRECOVERY&core=collection1&nodeName=127.0.0.1:45448_&coreNodeName=core_node4&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 534543 INFO (qtp19728315-6969) [ ] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true
[junit4] 2> 534544 INFO (qtp19728315-6969) [ ] o.a.s.h.a.PrepRecoveryOp Will wait a max of 183 seconds to see collection1 (shard1 of collection1) have state: recovering
[junit4] 2> 534544 INFO (qtp19728315-6969) [ ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard1, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:45448_, coreNodeName=core_node4, onlyIfActiveCheckResult=false, nodeProps: core_node4:{"core":"collection1","base_url":"http://127.0.0.1:45448","node_name":"127.0.0.1:45448_","state":"down"}
[junit4] 2> 534785 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testSplitWithChaosMonkey
[junit4] 2> 534785 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractFullDistribZkTestBase Wait for recoveries to finish - wait 15 for each attempt
[junit4] 2> 534785 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractDistribZkTestBase Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4] 2> 535544 INFO (qtp19728315-6969) [ ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard1, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=recovering, localState=active, nodeName=127.0.0.1:45448_, coreNodeName=core_node4, onlyIfActiveCheckResult=false, nodeProps: core_node4:{"core":"collection1","base_url":"http://127.0.0.1:45448","node_name":"127.0.0.1:45448_","state":"recovering"}
[junit4] 2> 535544 INFO (qtp19728315-6969) [ ] o.a.s.h.a.PrepRecoveryOp Waited coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4] 2> 535544 INFO (qtp19728315-6969) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:45448_&onlyIfLeaderActive=true&core=collection1&coreNodeName=core_node4&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=1001
[junit4] 2> 536045 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.c.RecoveryStrategy Attempting to PeerSync from [http://127.0.0.1:43223/collection1/] - recoveringAfterStartup=[true]
[junit4] 2> 536045 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.u.PeerSync PeerSync: core=collection1 url=http://127.0.0.1:45448 START replicas=[http://127.0.0.1:43223/collection1/] nUpdates=100
[junit4] 2> 536047 INFO (qtp19728315-6969) [ ] o.a.s.u.IndexFingerprint IndexFingerprint millis:0.0 result:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=0, maxInHash=0, versionsHash=0, numVersions=0, numDocs=0, maxDoc=0}
[junit4] 2> 536047 INFO (qtp19728315-6969) [ ] o.a.s.c.S.Request [collection1] webapp= path=/get params={distrib=false&qt=/get&getFingerprint=9223372036854775807&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 536047 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.u.IndexFingerprint IndexFingerprint millis:0.0 result:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=0, maxInHash=0, versionsHash=0, numVersions=0, numDocs=0, maxDoc=0}
[junit4] 2> 536047 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.u.PeerSync We are already in sync. No need to do a PeerSync
[junit4] 2> 536047 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 536047 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 536048 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 536048 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.c.RecoveryStrategy PeerSync stage of recovery was successful.
[junit4] 2> 536048 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.c.RecoveryStrategy Replaying updates buffered during PeerSync.
[junit4] 2> 536048 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.c.RecoveryStrategy No replay needed.
[junit4] 2> 536048 INFO (recoveryExecutor-1737-thread-1) [ ] o.a.s.c.RecoveryStrategy Registering as Active after recovery.
[junit4] 2> 536786 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[A77CD4947DE33092]) [ ] o.a.s.c.AbstractDistribZkTestBase Recoveries finished - collection: collection1
[junit4] 2> 536787 INFO (qtp18589169-6907) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 536787 INFO (qtp18589169-6907) [ ] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 536787 INFO (qtp18589169-6907) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 536787 INFO (qtp18589169-6907) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 0
[junit4] 2> 536789 INFO (qtp19728315-6966) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 536789 INFO (qtp19728315-6966) [ ] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 536789 INFO (qtp19001918-7032) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 536789 INFO (qtp21118466-6939) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 536789 INFO (qtp19001918-7032) [ ] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 536789 INFO (qtp19728315-6966) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 536789 INFO (qtp21118466-6939) [ ] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 536790 INFO (qtp19728315-6966) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:37824/collection1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 0
[junit4] 2> 536790 INFO (qtp19001918-7032) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 536790 INFO (qtp19001918-7032) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:37824/collection1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 0
[junit4] 2> 536790 INFO (qtp21118466-6939) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 536790 INFO (qtp31980512-6998) [ ] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 536790 INFO (qtp31980512-6998) [ ] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 536790 INFO (qtp21118466-6939) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:37824/collection1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 0
[junit4] 2> 536790 INFO (qtp31980512-6998) [ ] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 536790 INFO (qtp31980512-6998) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:37824/collection1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 0
[junit4] 2> 536790 INFO (qtp21118466-6938) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 2
[junit4] 2> 536792 INFO (qtp21118466-6943) [ ] o.a.s.c.S.Request [collection1] webapp= path=/select params={q=*:*&distrib=false&tests=checkShardConsistency&rows=0&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 536793 INFO (qtp31980512-6999) [ ] o.a.s.c.S.Request [collection1] webapp= path=/select params={q=*:*&distrib=false&tests=checkShardConsistency&rows=0&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 536796 INFO (qtp19728315-6969) [ ] o.a.s.c.S.Request [collection1] webapp= path=/select params={q=*:*&distrib=false&tests=checkShardConsistency&rows=0&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 536797 INFO (qtp19001918-7034) [ ] o.a.s.c.S.Request [collection1] webapp= path=/select params={q=*:*&distrib=false&tests=checkShardConsistency&rows=0&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 538802 INFO (qtp18589169-6909) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-0 (1566850265822265344)]} 0 2
[junit4] 2> 538809 INFO (qtp19001918-7032) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43223/collection1/&wt=javabin&version=2}{add=[0-0 (1566850265824362496)]} 0 2
[junit4] 2> 538809 INFO (qtp19728315-6971) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[0-0 (1566850265824362496)]} 0 5
[junit4] 2> 538811 INFO (qtp18589169-6908) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-1 (1566850265832751104)]} 0 0
[junit4] 2> 538816 INFO (qtp19001918-7028) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43223/collection1/&wt=javabin&version=2}{add=[0-1 (1566850265834848256)]} 0 0
[junit4] 2> 538816 INFO (qtp19728315-6966) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[0-1 (1566850265834848256)]} 0 3
[junit4] 2> 538818 INFO (qtp18589169-6902) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{delete=[0-0 (-1566850265840091136)]} 0 0
[junit4] 2> 538822 INFO (qtp19001918-7028) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43223/collection1/&wt=javabin&version=2}{delete=[0-0 (-1566850265843236864)]} 0 0
[junit4] 2> 538823 INFO (qtp19728315-6967) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{delete=[0-0 (-1566850265843236864)]} 0 2
[junit4] 2> 538825 INFO (qtp18589169-6907) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-2 (1566850265846382592)]} 0 1
[junit4] 2> 538829 INFO (qtp19001918-7028) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43223/collection1/&wt=javabin&version=2}{add=[0-2 (1566850265849528320)]} 0 0
[junit4] 2> 538830 INFO (qtp19728315-6969) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[0-2 (1566850265849528320)]} 0 2
[junit4] 2> 538831 INFO (qtp18589169-6909) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{delete=[0-1 (-1566850265853722624)]} 0 0
[junit4] 2> 538834 INFO (qtp19001918-7032) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43223/collection1/&wt=javabin&version=2}{delete=[0-1 (-1566850265855819776)]} 0 0
[junit4] 2> 538834 INFO (qtp19728315-6971) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{delete=[0-1 (-1566850265855819776)]} 0 1
[junit4] 2> 538836 INFO (qtp18589169-6908) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-3 (1566850265858965504)]} 0 0
[junit4] 2> 538840 INFO (qtp19001918-7034) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43223/collection1/&wt=javabin&version=2}{add=[0-3 (1566850265861062656)]} 0 0
[junit4] 2> 538841 INFO (qtp19728315-6966) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[0-3 (1566850265861062656)]} 0 2
[junit4] 2> 538843 INFO (qtp18589169-6902) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{delete=[0-3 (-1566850265866305536)]} 0 0
[junit4] 2> 538847 INFO (qtp19001918-7029) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43223/collection1/&wt=javabin&version=2}{delete=[0-3 (-1566850265868402688)]} 0 0
[junit4] 2> 538847 INFO (qtp19728315-6967) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{delete=[0-3 (-1566850265868402688)]} 0 2
[junit4] 2> 538849 INFO (qtp18589169-6907) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-4 (1566850265871548416)]} 0 0
[junit4] 2> 538853 INFO (qtp19001918-7028) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43223/collection1/&wt=javabin&version=2}{add=[0-4 (1566850265874694144)]} 0 0
[junit4] 2> 538853 INFO (qtp19728315-6969) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[0-4 (1566850265874694144)]} 0 2
[junit4] 2> 538855 INFO (qtp18589169-6909) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{delete=[0-4 (-1566850265878888448)]} 0 0
[junit4] 2> 538858 INFO (qtp19001918-7032) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43223/collection1/&wt=javabin&version=2}{delete=[0-4 (-1566850265880985600)]} 0 0
[junit4] 2> 538859 INFO (qtp19728315-6971) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{delete=[0-4 (-1566850265880985600)]} 0 1
[junit4] 2> 538861 INFO (qtp18589169-6908) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-5 (1566850265884131328)]} 0 0
[junit4] 2> 538866 INFO (qtp31980512-6997) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:37824/collection1/&wt=javabin&version=2}{add=[0-5 (1566850265886228480)]} 0 1
[junit4] 2> 538866 INFO (qtp21118466-6936) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[0-5 (1566850265886228480)]} 0 4
[junit4] 2> 538869 INFO (qtp18589169-6902) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-6 (1566850265892519936)]} 0 1
[junit4] 2> 538873 INFO (qtp31980512-6998) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:37824/collection1/&wt=javabin&version=2}{add=[0-6 (1566850265895665664)]} 0 0
[junit4] 2> 538873 INFO (qtp21118466-6939) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[0-6 (1566850265895665664)]} 0 2
[junit4] 2> 538875 INFO (qtp18589169-6907) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-7 (1566850265899859968)]} 0 0
[junit4] 2> 538879 INFO (qtp31980512-6993) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:37824/collection1/&wt=javabin&version=2}{add=[0-7 (1566850265901957120)]} 0 0
[junit4] 2> 538879 INFO (qtp21118466-6938) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[0-7 (1566850265901957120)]} 0 2
[junit4] 2> 538881 INFO (qtp18589169-6909) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-8 (1566850265906151424)]} 0 0
[junit4] 2> 538885 INFO (qtp31980512-6992) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:37824/collection1/&wt=javabin&version=2}{add=[0-8 (1566850265908248576)]} 0 0
[junit4] 2> 538885 INFO (qtp21118466-6943) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[0-8 (1566850265908248576)]} 0 2
[junit4] 2> 538887 INFO (qtp18589169-6908) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-9 (1566850265912442880)]} 0 0
[junit4] 2> 538890 INFO (qtp31980512-6997) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:37824/collection1/&wt=javabin&version=2}{add=[0-9 (1566850265913491456)]} 0 0
[junit4] 2> 538890 INFO (qtp21118466-6936) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2}{add=[0-9 (1566850265913491456)]} 0 1
[junit4] 2> 538892 INFO (qtp18589169-6902) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={wt=javabin&version=2&CONTROL=TRUE}{add=[0-10 (1566850265917685760)]} 0 0
[junit4] 2> 538896 INFO (qtp19001918-7034) [ ] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:43223/collection1/&wt=javabin&version=2}{add=[0-10 (1566850265919782912)]} 0 0
[junit4] 2> 538896 INFO (qtp19728315-6966) [ ] o.a.s.u.p.LogUpdat
[...truncated too long message...]
litByRouteKeyTest_shard1_replica2] CLOSING SolrCore org.apache.solr.core.SolrCore@14a139a
[junit4] 2> 1307443 INFO (coreCloseExecutor-3991-thread-8) [ ] o.a.s.c.SolrCore [splitByRouteKeyTest_shard1_0_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@1c4fbdf
[junit4] 2> 1307443 INFO (coreCloseExecutor-3991-thread-5) [ ] o.a.s.c.SolrCore [routeFieldColl_shard1_1_replica0] CLOSING SolrCore org.apache.solr.core.SolrCore@2e626a
[junit4] 2> 1307446 INFO (zkCallback-1912-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/splitByRouteKeyTest/state.json] for collection [splitByRouteKeyTest] has occurred - updating... (live nodes size: [1])
[junit4] 2> 1307446 INFO (zkCallback-1912-thread-4) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/splitByRouteKeyTest/state.json] for collection [splitByRouteKeyTest] has occurred - updating... (live nodes size: [1])
[junit4] 2> 1307448 INFO (coreCloseExecutor-3991-thread-11) [ ] o.a.s.c.SolrCore [splitByRouteKeyTest_shard1_1_replica0] CLOSING SolrCore org.apache.solr.core.SolrCore@11b7f30
[junit4] 2> 1307557 INFO (zkCallback-1912-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/routeFieldColl/state.json] for collection [routeFieldColl] has occurred - updating... (live nodes size: [1])
[junit4] 2> 1307557 INFO (zkCallback-1912-thread-4) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/routeFieldColl/state.json] for collection [routeFieldColl] has occurred - updating... (live nodes size: [1])
[junit4] 2> 1307866 INFO (coreCloseExecutor-3991-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.collection1.shard1_1.replica0
[junit4] 2> 1308074 INFO (coreCloseExecutor-3991-thread-5) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.routeFieldColl.shard1_1.replica0
[junit4] 2> 1308251 INFO (coreCloseExecutor-3991-thread-3) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.routeFieldColl.shard4.replica1
[junit4] 2> 1308269 INFO (coreCloseExecutor-3991-thread-6) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.splitByRouteKeyTest.shard4.replica1
[junit4] 2> 1308274 INFO (coreCloseExecutor-3991-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.collection1
[junit4] 2> 1308294 INFO (coreCloseExecutor-3991-thread-8) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.splitByRouteKeyTest.shard1_0.replica1
[junit4] 2> 1308304 INFO (coreCloseExecutor-3991-thread-9) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.splitByRouteKeyTest.shard1_1.replica1
[junit4] 2> 1308310 INFO (coreCloseExecutor-3991-thread-7) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.splitByRouteKeyTest.shard1.replica2
[junit4] 2> 1308310 INFO (coreCloseExecutor-3991-thread-10) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.splitByRouteKeyTest.shard1_2.replica1
[junit4] 2> 1308311 INFO (coreCloseExecutor-3991-thread-4) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.routeFieldColl.shard1.replica2
[junit4] 2> 1308313 INFO (coreCloseExecutor-3991-thread-11) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.splitByRouteKeyTest.shard1_1.replica0
[junit4] 2> 1308314 INFO (TEST-ShardSplitTest.test-seed#[A77CD4947DE33092]) [ ] o.a.s.c.Overseer Overseer (id=97928179073941522-127.0.0.1:40737_-n_0000000004) closing
[junit4] 2> 1308315 INFO (OverseerStateUpdate-97928179073941522-127.0.0.1:40737_-n_0000000004) [ ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:40737_
[junit4] 2> 1308316 INFO (zkCallback-1920-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0)
[junit4] 2> 1308316 INFO (zkCallback-1887-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0)
[junit4] 2> 1309816 WARN (zkCallback-1912-thread-2) [ ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 1309817 INFO (TEST-ShardSplitTest.test-seed#[A77CD4947DE33092]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@176f089{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1309818 INFO (TEST-ShardSplitTest.test-seed#[A77CD4947DE33092]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@4e1085{/,null,UNAVAILABLE}
[junit4] 2> 1309821 INFO (TEST-ShardSplitTest.test-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ChaosMonkey monkey: stop shard! 42166
[junit4] 2> 1309821 ERROR (TEST-ShardSplitTest.test-seed#[A77CD4947DE33092]) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 1309821 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x15be928f7340005, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> 1309822 INFO (TEST-ShardSplitTest.test-seed#[A77CD4947DE33092]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:33403 33403
[junit4] 2> 1309828 INFO (Thread-1568) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:33403 33403
[junit4] 2> 1309829 WARN (Thread-1568) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 9 /solr/aliases.json
[junit4] 2> 6 /solr/clusterprops.json
[junit4] 2> 5 /solr/security.json
[junit4] 2> 5 /solr/configs/conf1
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 160 /solr/collections/splitByRouteKeyTest/state.json
[junit4] 2> 142 /solr/collections/routeFieldColl/state.json
[junit4] 2> 9 /solr/clusterprops.json
[junit4] 2> 9 /solr/clusterstate.json
[junit4] 2> 4 /solr/collections/collection1/state.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 9 /solr/live_nodes
[junit4] 2> 9 /solr/collections
[junit4] 2> 5 /solr/overseer/queue
[junit4] 2> 5 /solr/overseer/collection-queue-work
[junit4] 2> 4 /solr/overseer/queue-work
[junit4] 2>
[junit4] 2> 1309831 INFO (SUITE-ShardSplitTest-seed#[A77CD4947DE33092]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_A77CD4947DE33092-001
[junit4] 2> May 08, 2017 5:47:07 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 3 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62), sim=RandomSimilarity(queryNorm=true,coord=yes): {}, locale=fr-ML, timezone=Pacific/Pitcairn
[junit4] 2> NOTE: Linux 4.4.0-75-generic i386/Oracle Corporation 9-ea (32-bit)/cpus=12,threads=1,free=131776264,total=333389824
[junit4] 2> NOTE: All tests run in this JVM: [OverseerTest, TestFileDictionaryLookup, HdfsRestartWhileUpdatingTest, StatsReloadRaceTest, TestBinaryField, BigEndianAscendingWordSerializerTest, NoCacheHeaderTest, TestDistributedMissingSort, TestRecoveryHdfs, BinaryUpdateRequestHandlerTest, TestDynamicFieldResource, CollectionTooManyReplicasTest, HdfsTlogReplayBufferedWhileIndexingTest, ReplicaListTransformerTest, TestSolrQueryResponse, FieldAnalysisRequestHandlerTest, TestHdfsCloudBackupRestore, TestTolerantUpdateProcessorRandomCloud, ResponseLogComponentTest, TestMacros, AnalyticsQueryTest, SolrCoreCheckLockOnStartupTest, TestExceedMaxTermLength, BadComponentTest, MigrateRouteKeyTest, DistribDocExpirationUpdateProcessorTest, SuggesterTest, StatsComponentTest, TestBinaryResponseWriter, DistributedSuggestComponentTest, TestClassNameShortening, SuggestComponentContextFilterQueryTest, TestUniqueKeyFieldResource, DateRangeFieldTest, CircularListTest, SolrTestCaseJ4Test, TestCollectionAPI, TestExactStatsCache, XmlUpdateRequestHandlerTest, CurrencyFieldXmlFileTest, TestNRTOpen, ZkStateWriterTest, AddSchemaFieldsUpdateProcessorFactoryTest, AutoCommitTest, BadIndexSchemaTest, PluginInfoTest, TestWriterPerf, ActionThrottleTest, TestCorePropertiesReload, TestMultiWordSynonyms, TestSolrConfigHandlerCloud, SolrSlf4jReporterTest, JSONWriterTest, TestSort, TestRecovery, BlockJoinFacetSimpleTest, TestSubQueryTransformerCrossCore, CreateCollectionCleanupTest, TestDistribDocBasedVersion, UpdateParamsTest, TestSimpleTextCodec, TestNumericTerms64, OverseerRolesTest, TestRestoreCore, DistributedVersionInfoTest, TestDFRSimilarityFactory, TestManagedSchema, SimpleFacetsTest, TestSolrQueryParser, TestSolrDeletionPolicy1, CoreAdminHandlerTest, TestRequestStatusCollectionAPI, TestHdfsBackupRestoreCore, RulesTest, DeleteLastCustomShardedReplicaTest, PreAnalyzedFieldTest, TestFieldCacheWithThreads, TestConfigSetsAPIZkFailure, ShardSplitTest]
[junit4] Completed [432/711 (1!)] on J2 in 785.20s, 5 tests, 1 failure <<< FAILURES!
[...truncated 37280 lines...]
[JENKINS] Lucene-Solr-6.x-Linux (64bit/jdk1.8.0_131) - Build # 3470
- Still Unstable!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-6.x-Linux/3470/
Java: 64bit/jdk1.8.0_131 -XX:-UseCompressedOops -XX:+UseSerialGC
1 tests failed.
FAILED: org.apache.solr.cloud.ShardSplitTest.testSplitWithChaosMonkey
Error Message:
There are still nodes recoverying - waited for 330 seconds
Stack Trace:
java.lang.AssertionError: There are still nodes recoverying - waited for 330 seconds
at __randomizedtesting.SeedInfo.seed([E80FC51C3CA9E5F9:632816CD7DAF4E7D]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:187)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:144)
at org.apache.solr.cloud.AbstractDistribZkTestBase.waitForRecoveriesToFinish(AbstractDistribZkTestBase.java:139)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.waitForRecoveriesToFinish(AbstractFullDistribZkTestBase.java:856)
at org.apache.solr.cloud.ShardSplitTest.testSplitWithChaosMonkey(ShardSplitTest.java:437)
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:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:992)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:967)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
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:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
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:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:748)
Build Log:
[...truncated 11870 lines...]
[junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/init-core-data-001
[junit4] 2> 50577 WARN (SUITE-ShardSplitTest-seed#[E80FC51C3CA9E5F9]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=3 numCloses=3
[junit4] 2> 50577 INFO (SUITE-ShardSplitTest-seed#[E80FC51C3CA9E5F9]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields
[junit4] 2> 50579 INFO (SUITE-ShardSplitTest-seed#[E80FC51C3CA9E5F9]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl=https://issues.apache.org/jira/browse/SOLR-5776)
[junit4] 2> 50579 INFO (SUITE-ShardSplitTest-seed#[E80FC51C3CA9E5F9]-worker) [ ] o.a.s.BaseDistributedSearchTestCase Setting hostContext system property: /_a/ac
[junit4] 2> 50582 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 50582 INFO (Thread-109) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 50582 INFO (Thread-109) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 50587 ERROR (Thread-109) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 50682 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ZkTestServer start zk server on port:39217
[junit4] 2> 50720 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 50722 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4] 2> 50723 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 50724 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 50725 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 50726 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 50727 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
[junit4] 2> 50728 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 50729 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 50730 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 50731 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractZkTestCase put /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/core/src/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 50828 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/control-001/cores/collection1
[junit4] 2> 50831 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 50835 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@16157e3a{/_a/ac,null,AVAILABLE}
[junit4] 2> 50836 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@14c53ade{HTTP/1.1,[http/1.1]}{127.0.0.1:42698}
[junit4] 2> 50836 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.Server Started @53186ms
[junit4] 2> 50836 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/tempDir-001/control/data, hostContext=/_a/ac, hostPort=42698, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/control-001/cores}
[junit4] 2> 50837 ERROR (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 50837 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.0
[junit4] 2> 50837 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 50837 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 50842 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-05-08T20:13:32.473Z
[junit4] 2> 50858 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 50858 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/control-001/solr.xml
[junit4] 2> 50869 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 50871 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39217/solr
[junit4] 2> 50918 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 50919 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:42698__a%2Fac
[junit4] 2> 50921 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.Overseer Overseer (id=97928767879118852-127.0.0.1:42698__a%2Fac-n_0000000000) starting
[junit4] 2> 50933 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42698__a%2Fac
[junit4] 2> 50934 INFO (zkCallback-70-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 51036 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/control-001/cores
[junit4] 2> 51037 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 51042 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 51051 INFO (OverseerStateUpdate-97928767879118852-127.0.0.1:42698__a%2Fac-n_0000000000) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 52060 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.0
[junit4] 2> 52073 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 52156 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 52168 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection control_collection, trusted=true
[junit4] 2> 52172 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 52172 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/control-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/control-001/cores/collection1/data/]
[junit4] 2> 52172 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@c05b1d6
[junit4] 2> 52175 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=22, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 52216 WARN (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 52258 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 52258 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 52259 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 52259 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 52260 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=17, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.13238838379561405]
[junit4] 2> 52260 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@51572b4b[collection1] main]
[junit4] 2> 52261 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 52262 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 52262 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 52263 INFO (searcherExecutor-294-thread-1-processing-n:127.0.0.1:42698__a%2Fac x:collection1 c:control_collection) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@51572b4b[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 52264 INFO (coreLoadExecutor-293-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac c:control_collection x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1566860287824363520
[junit4] 2> 52269 INFO (coreZkRegister-286-thread-1-processing-n:127.0.0.1:42698__a%2Fac x:collection1 c:control_collection) [n:127.0.0.1:42698__a%2Fac c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 52269 INFO (coreZkRegister-286-thread-1-processing-n:127.0.0.1:42698__a%2Fac x:collection1 c:control_collection) [n:127.0.0.1:42698__a%2Fac 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> 52269 INFO (coreZkRegister-286-thread-1-processing-n:127.0.0.1:42698__a%2Fac x:collection1 c:control_collection) [n:127.0.0.1:42698__a%2Fac c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:42698/_a/ac/collection1/
[junit4] 2> 52269 INFO (coreZkRegister-286-thread-1-processing-n:127.0.0.1:42698__a%2Fac x:collection1 c:control_collection) [n:127.0.0.1:42698__a%2Fac c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 52269 INFO (coreZkRegister-286-thread-1-processing-n:127.0.0.1:42698__a%2Fac x:collection1 c:control_collection) [n:127.0.0.1:42698__a%2Fac c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:42698/_a/ac/collection1/ has no replicas
[junit4] 2> 52269 INFO (coreZkRegister-286-thread-1-processing-n:127.0.0.1:42698__a%2Fac x:collection1 c:control_collection) [n:127.0.0.1:42698__a%2Fac c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 52272 INFO (coreZkRegister-286-thread-1-processing-n:127.0.0.1:42698__a%2Fac x:collection1 c:control_collection) [n:127.0.0.1:42698__a%2Fac 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:42698/_a/ac/collection1/ shard1
[junit4] 2> 52423 INFO (coreZkRegister-286-thread-1-processing-n:127.0.0.1:42698__a%2Fac x:collection1 c:control_collection) [n:127.0.0.1:42698__a%2Fac c:control_collection s:shard1 r:core_node1 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 52569 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 52571 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:39217/solr ready
[junit4] 2> 52573 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ChaosMonkey monkey: init - expire sessions:false cause connection loss:false
[junit4] 2> 52642 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-1-001/cores/collection1
[junit4] 2> 52643 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 1 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-1-001
[junit4] 2> 52644 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 52644 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@690e66f{/_a/ac,null,AVAILABLE}
[junit4] 2> 52645 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@37fa5a89{HTTP/1.1,[http/1.1]}{127.0.0.1:35074}
[junit4] 2> 52645 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.Server Started @54995ms
[junit4] 2> 52645 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/tempDir-001/jetty1, solrconfig=solrconfig.xml, hostContext=/_a/ac, hostPort=35074, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-1-001/cores}
[junit4] 2> 52645 ERROR (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 52646 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.0
[junit4] 2> 52646 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 52646 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 52646 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-05-08T20:13:34.277Z
[junit4] 2> 52648 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 52648 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-1-001/solr.xml
[junit4] 2> 52656 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 52656 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39217/solr
[junit4] 2> 52666 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:35074__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 52668 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:35074__a%2Fac ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 52671 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:35074__a%2Fac ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35074__a%2Fac
[junit4] 2> 52673 INFO (zkCallback-79-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 52678 INFO (zkCallback-70-thread-1-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 52679 INFO (zkCallback-74-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 52822 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:35074__a%2Fac ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-1-001/cores
[junit4] 2> 52822 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:35074__a%2Fac ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 52823 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 52828 INFO (OverseerStateUpdate-97928767879118852-127.0.0.1:42698__a%2Fac-n_0000000000) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 53841 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.0
[junit4] 2> 53855 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 53962 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 53975 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1, trusted=true
[junit4] 2> 53975 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 53975 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-1-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-1-001/cores/collection1/data/]
[junit4] 2> 53975 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@c05b1d6
[junit4] 2> 53978 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=22, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 54048 WARN (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 54083 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 54083 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 54084 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 54084 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 54085 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=17, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.13238838379561405]
[junit4] 2> 54086 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@15dbeab8[collection1] main]
[junit4] 2> 54087 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 54087 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 54087 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 54089 INFO (searcherExecutor-305-thread-1-processing-n:127.0.0.1:35074__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@15dbeab8[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 54090 INFO (coreLoadExecutor-304-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1566860289739063296
[junit4] 2> 54096 INFO (coreZkRegister-299-thread-1-processing-n:127.0.0.1:35074__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:35074__a%2Fac c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 54096 INFO (coreZkRegister-299-thread-1-processing-n:127.0.0.1:35074__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:35074__a%2Fac c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 54096 INFO (coreZkRegister-299-thread-1-processing-n:127.0.0.1:35074__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:35074__a%2Fac c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:35074/_a/ac/collection1/
[junit4] 2> 54096 INFO (coreZkRegister-299-thread-1-processing-n:127.0.0.1:35074__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:35074__a%2Fac c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 54096 INFO (coreZkRegister-299-thread-1-processing-n:127.0.0.1:35074__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:35074__a%2Fac c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:35074/_a/ac/collection1/ has no replicas
[junit4] 2> 54096 INFO (coreZkRegister-299-thread-1-processing-n:127.0.0.1:35074__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:35074__a%2Fac c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 54098 INFO (coreZkRegister-299-thread-1-processing-n:127.0.0.1:35074__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:35074__a%2Fac c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:35074/_a/ac/collection1/ shard2
[junit4] 2> 54249 INFO (coreZkRegister-299-thread-1-processing-n:127.0.0.1:35074__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:35074__a%2Fac c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 54395 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-2-001/cores/collection1
[junit4] 2> 54395 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 2 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-2-001
[junit4] 2> 54396 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 54397 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@adf80f3{/_a/ac,null,AVAILABLE}
[junit4] 2> 54397 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@5d413024{HTTP/1.1,[http/1.1]}{127.0.0.1:42086}
[junit4] 2> 54398 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.Server Started @56748ms
[junit4] 2> 54398 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/tempDir-001/jetty2, solrconfig=solrconfig.xml, hostContext=/_a/ac, hostPort=42086, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-2-001/cores}
[junit4] 2> 54398 ERROR (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 54398 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.0
[junit4] 2> 54398 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 54398 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 54398 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-05-08T20:13:36.029Z
[junit4] 2> 54401 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 54401 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-2-001/solr.xml
[junit4] 2> 54407 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 54408 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39217/solr
[junit4] 2> 54419 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42086__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 54420 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42086__a%2Fac ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 54422 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42086__a%2Fac ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42086__a%2Fac
[junit4] 2> 54423 INFO (zkCallback-74-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 54423 INFO (zkCallback-70-thread-2-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 54423 INFO (zkCallback-85-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 54425 INFO (zkCallback-79-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (3)
[junit4] 2> 54535 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42086__a%2Fac ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-2-001/cores
[junit4] 2> 54536 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:42086__a%2Fac ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 54545 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 54547 INFO (OverseerStateUpdate-97928767879118852-127.0.0.1:42698__a%2Fac-n_0000000000) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 55558 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.0
[junit4] 2> 55569 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 55699 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 55712 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1, trusted=true
[junit4] 2> 55712 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 55713 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-2-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-2-001/cores/collection1/data/]
[junit4] 2> 55713 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@c05b1d6
[junit4] 2> 55716 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=22, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 55755 WARN (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 55786 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 55786 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 55787 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 55787 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 55788 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=17, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.13238838379561405]
[junit4] 2> 55788 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@14fe1534[collection1] main]
[junit4] 2> 55789 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 55790 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 55790 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 55791 INFO (searcherExecutor-316-thread-1-processing-n:127.0.0.1:42086__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@14fe1534[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 55792 INFO (coreLoadExecutor-315-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1566860291523739648
[junit4] 2> 55796 INFO (coreZkRegister-310-thread-1-processing-n:127.0.0.1:42086__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:42086__a%2Fac c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 55796 INFO (coreZkRegister-310-thread-1-processing-n:127.0.0.1:42086__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:42086__a%2Fac c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 55796 INFO (coreZkRegister-310-thread-1-processing-n:127.0.0.1:42086__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:42086__a%2Fac c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:42086/_a/ac/collection1/
[junit4] 2> 55796 INFO (coreZkRegister-310-thread-1-processing-n:127.0.0.1:42086__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:42086__a%2Fac c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 55796 INFO (coreZkRegister-310-thread-1-processing-n:127.0.0.1:42086__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:42086__a%2Fac c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:42086/_a/ac/collection1/ has no replicas
[junit4] 2> 55796 INFO (coreZkRegister-310-thread-1-processing-n:127.0.0.1:42086__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:42086__a%2Fac c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 55799 INFO (coreZkRegister-310-thread-1-processing-n:127.0.0.1:42086__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:42086__a%2Fac c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:42086/_a/ac/collection1/ shard1
[junit4] 2> 55950 INFO (coreZkRegister-310-thread-1-processing-n:127.0.0.1:42086__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:42086__a%2Fac c:collection1 s:shard1 r:core_node2 x:collection1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 56137 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-3-001/cores/collection1
[junit4] 2> 56138 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 3 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-3-001
[junit4] 2> 56138 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 56139 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@34c76848{/_a/ac,null,AVAILABLE}
[junit4] 2> 56140 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@453d8485{HTTP/1.1,[http/1.1]}{127.0.0.1:44928}
[junit4] 2> 56140 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.Server Started @58490ms
[junit4] 2> 56140 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/tempDir-001/jetty3, solrconfig=solrconfig.xml, hostContext=/_a/ac, hostPort=44928, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-3-001/cores}
[junit4] 2> 56140 ERROR (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 56144 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.0
[junit4] 2> 56144 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 56144 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 56144 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-05-08T20:13:37.775Z
[junit4] 2> 56153 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 56153 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-3-001/solr.xml
[junit4] 2> 56162 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 56163 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39217/solr
[junit4] 2> 56178 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:44928__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (3)
[junit4] 2> 56180 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:44928__a%2Fac ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 56182 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:44928__a%2Fac ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44928__a%2Fac
[junit4] 2> 56184 INFO (zkCallback-79-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 56185 INFO (zkCallback-70-thread-2-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 56185 INFO (zkCallback-85-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 56185 INFO (zkCallback-74-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 56186 INFO (zkCallback-91-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (3) -> (4)
[junit4] 2> 56251 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:44928__a%2Fac ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-3-001/cores
[junit4] 2> 56251 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:44928__a%2Fac ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 56252 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 56255 INFO (OverseerStateUpdate-97928767879118852-127.0.0.1:42698__a%2Fac-n_0000000000) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard2
[junit4] 2> 57280 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.0
[junit4] 2> 57292 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 57368 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 57379 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1, trusted=true
[junit4] 2> 57379 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 57379 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-3-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-3-001/cores/collection1/data/]
[junit4] 2> 57379 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@c05b1d6
[junit4] 2> 57381 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=22, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 57421 WARN (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 57460 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 57460 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 57461 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 57461 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 57462 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=17, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.13238838379561405]
[junit4] 2> 57462 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@36987b4e[collection1] main]
[junit4] 2> 57463 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 57464 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 57464 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 57466 INFO (searcherExecutor-327-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@36987b4e[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 57468 INFO (coreLoadExecutor-326-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1566860293281153024
[junit4] 2> 57472 INFO (coreZkRegister-321-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.ZkController Core needs to recover:collection1
[junit4] 2> 57473 INFO (updateExecutor-88-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 57477 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 57478 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 57478 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[collection1]
[junit4] 2> 57478 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 57478 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Publishing state of core [collection1] as recovering, leader is [http://127.0.0.1:35074/_a/ac/collection1/] and I am [http://127.0.0.1:44928/_a/ac/collection1/]
[junit4] 2> 57490 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:35074/_a/ac]; [WaitForState: action=PREPRECOVERY&core=collection1&nodeName=127.0.0.1:44928__a%252Fac&coreNodeName=core_node3&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 57494 INFO (qtp957385915-462) [n:127.0.0.1:35074__a%2Fac ] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true
[junit4] 2> 57495 INFO (qtp957385915-462) [n:127.0.0.1:35074__a%2Fac ] o.a.s.h.a.PrepRecoveryOp Will wait a max of 183 seconds to see collection1 (shard2 of collection1) have state: recovering
[junit4] 2> 57495 INFO (qtp957385915-462) [n:127.0.0.1:35074__a%2Fac ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard2, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:44928__a%2Fac, coreNodeName=core_node3, onlyIfActiveCheckResult=false, nodeProps: core_node3:{"core":"collection1","base_url":"http://127.0.0.1:44928/_a/ac","node_name":"127.0.0.1:44928__a%2Fac","state":"down"}
[junit4] 2> 57848 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-4-001/cores/collection1
[junit4] 2> 57849 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.AbstractFullDistribZkTestBase create jetty 4 in directory /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-4-001
[junit4] 2> 57850 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 57851 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2c4a21e3{/_a/ac,null,AVAILABLE}
[junit4] 2> 57852 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@2d81b656{HTTP/1.1,[http/1.1]}{127.0.0.1:45762}
[junit4] 2> 57852 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.Server Started @60202ms
[junit4] 2> 57852 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/tempDir-001/jetty4, solrconfig=solrconfig.xml, hostContext=/_a/ac, hostPort=45762, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-4-001/cores}
[junit4] 2> 57852 ERROR (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 57852 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 6.6.0
[junit4] 2> 57852 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 57853 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 57853 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-05-08T20:13:39.484Z
[junit4] 2> 57856 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.s.SolrDispatchFilter Loading solr.xml from SolrHome (not found in ZooKeeper)
[junit4] 2> 57856 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-4-001/solr.xml
[junit4] 2> 57883 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 57884 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:39217/solr
[junit4] 2> 57893 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:45762__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (4)
[junit4] 2> 57894 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:45762__a%2Fac ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 57896 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:45762__a%2Fac ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45762__a%2Fac
[junit4] 2> 57897 INFO (zkCallback-74-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 57897 INFO (zkCallback-79-thread-1-processing-n:127.0.0.1:35074__a%2Fac) [n:127.0.0.1:35074__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 57898 INFO (zkCallback-70-thread-2-processing-n:127.0.0.1:42698__a%2Fac) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 57897 INFO (zkCallback-91-thread-1-processing-n:127.0.0.1:44928__a%2Fac) [n:127.0.0.1:44928__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 57898 INFO (zkCallback-85-thread-1-processing-n:127.0.0.1:42086__a%2Fac) [n:127.0.0.1:42086__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 57902 INFO (zkCallback-98-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (4) -> (5)
[junit4] 2> 58124 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:45762__a%2Fac ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-4-001/cores
[junit4] 2> 58124 INFO (TEST-ShardSplitTest.testSplitWithChaosMonkey-seed#[E80FC51C3CA9E5F9]) [n:127.0.0.1:45762__a%2Fac ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 58124 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 4 transient cores
[junit4] 2> 58126 INFO (OverseerStateUpdate-97928767879118852-127.0.0.1:42698__a%2Fac-n_0000000000) [n:127.0.0.1:42698__a%2Fac ] o.a.s.c.o.ReplicaMutator Assigning new node to shard shard=shard1
[junit4] 2> 58495 INFO (qtp957385915-462) [n:127.0.0.1:35074__a%2Fac ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard2, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=recovering, localState=active, nodeName=127.0.0.1:44928__a%2Fac, coreNodeName=core_node3, onlyIfActiveCheckResult=false, nodeProps: core_node3:{"core":"collection1","base_url":"http://127.0.0.1:44928/_a/ac","node_name":"127.0.0.1:44928__a%2Fac","state":"recovering"}
[junit4] 2> 58495 INFO (qtp957385915-462) [n:127.0.0.1:35074__a%2Fac ] o.a.s.h.a.PrepRecoveryOp Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4] 2> 58496 INFO (qtp957385915-462) [n:127.0.0.1:35074__a%2Fac ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={nodeName=127.0.0.1:44928__a%252Fac&onlyIfLeaderActive=true&core=collection1&coreNodeName=core_node3&action=PREPRECOVERY&checkLive=true&state=recovering&onlyIfLeader=true&wt=javabin&version=2} status=0 QTime=1002
[junit4] 2> 58997 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Attempting to PeerSync from [http://127.0.0.1:35074/_a/ac/collection1/] - recoveringAfterStartup=[true]
[junit4] 2> 58997 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.PeerSync PeerSync: core=collection1 url=http://127.0.0.1:44928/_a/ac START replicas=[http://127.0.0.1:35074/_a/ac/collection1/] nUpdates=100
[junit4] 2> 59002 INFO (qtp957385915-462) [n:127.0.0.1:35074__a%2Fac c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.u.IndexFingerprint IndexFingerprint millis:1.0 result:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=0, maxInHash=0, versionsHash=0, numVersions=0, numDocs=0, maxDoc=0}
[junit4] 2> 59002 INFO (qtp957385915-462) [n:127.0.0.1:35074__a%2Fac c:collection1 s:shard2 r:core_node1 x:collection1] o.a.s.c.S.Request [collection1] webapp=/_a/ac path=/get params={distrib=false&qt=/get&getFingerprint=9223372036854775807&wt=javabin&version=2} status=0 QTime=1
[junit4] 2> 59003 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.IndexFingerprint IndexFingerprint millis:0.0 result:{maxVersionSpecified=9223372036854775807, maxVersionEncountered=0, maxInHash=0, versionsHash=0, numVersions=0, numDocs=0, maxDoc=0}
[junit4] 2> 59003 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.PeerSync We are already in sync. No need to do a PeerSync
[junit4] 2> 59003 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 59003 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 59004 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 59004 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy PeerSync stage of recovery was successful.
[junit4] 2> 59004 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Replaying updates buffered during PeerSync.
[junit4] 2> 59004 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy No replay needed.
[junit4] 2> 59004 INFO (recoveryExecutor-89-thread-1-processing-n:127.0.0.1:44928__a%2Fac x:collection1 s:shard2 c:collection1 r:core_node3) [n:127.0.0.1:44928__a%2Fac c:collection1 s:shard2 r:core_node3 x:collection1] o.a.s.c.RecoveryStrategy Registering as Active after recovery.
[junit4] 2> 59142 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.6.0
[junit4] 2> 59160 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 59269 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.6 with uniqueid field id
[junit4] 2> 59283 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from collection collection1, trusted=true
[junit4] 2> 59284 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 59284 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-4-001/cores/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/../../../../../../../../../home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001/shard-4-001/cores/collection1/data/]
[junit4] 2> 59284 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@c05b1d6
[junit4] 2> 59287 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=22, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 59331 WARN (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.c.RequestHandlers INVALID paramSet a in requestHandler {type = requestHandler,name = /dump,class = DumpRequestHandler,attributes = {initParams=a, name=/dump, class=DumpRequestHandler},args = {defaults={a=A,b=B}}}
[junit4] 2> 59390 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 59390 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 59391 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 59391 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 59392 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=17, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.13238838379561405]
[junit4] 2> 59393 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@3aadb618[collection1] main]
[junit4] 2> 59394 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 59394 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 59394 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 59397 INFO (searcherExecutor-338-thread-1-processing-n:127.0.0.1:45762__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@3aadb618[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 59398 INFO (coreLoadExecutor-337-thread-1-processing-n:127.0.0.1:45762__a%2Fac) [n:127.0.0.1:45762__a%2Fac c:collection1 x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1566860295304904704
[junit4] 2> 59402 INFO (coreZkRegister-332-thread-1-processing-n:127.0.0.1:45762__a%2Fac x:collection1 c:collection1) [n:127.0.0.1:45762__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.ZkController Core needs to recover:collection1
[junit4] 2> 59402 INFO (updateExecutor-95-thread-1-processing-n:127.0.0.1:45762__a%2Fac x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:45762__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.u.DefaultSolrCoreState Running recovery
[junit4] 2> 59402 INFO (recoveryExecutor-96-thread-1-processing-n:127.0.0.1:45762__a%2Fac x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:45762__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.RecoveryStrategy Starting recovery process. recoveringAfterStartup=true
[junit4] 2> 59403 INFO (recoveryExecutor-96-thread-1-processing-n:127.0.0.1:45762__a%2Fac x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:45762__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.RecoveryStrategy ###### startupVersions=[[]]
[junit4] 2> 59403 INFO (recoveryExecutor-96-thread-1-processing-n:127.0.0.1:45762__a%2Fac x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:45762__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.RecoveryStrategy Begin buffering updates. core=[collection1]
[junit4] 2> 59403 INFO (recoveryExecutor-96-thread-1-processing-n:127.0.0.1:45762__a%2Fac x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:45762__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.u.UpdateLog Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4] 2> 59403 INFO (recoveryExecutor-96-thread-1-processing-n:127.0.0.1:45762__a%2Fac x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:45762__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.RecoveryStrategy Publishing state of core [collection1] as recovering, leader is [http://127.0.0.1:42086/_a/ac/collection1/] and I am [http://127.0.0.1:45762/_a/ac/collection1/]
[junit4] 2> 59405 INFO (recoveryExecutor-96-thread-1-processing-n:127.0.0.1:45762__a%2Fac x:collection1 s:shard1 c:collection1 r:core_node4) [n:127.0.0.1:45762__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.RecoveryStrategy Sending prep recovery command to [http://127.0.0.1:42086/_a/ac]; [WaitForState: action=PREPRECOVERY&core=collection1&nodeName=127.0.0.1:45762__a%252Fac&coreNodeName=core_node4&state=recovering&checkLive=true&onlyIfLeader=true&onlyIfLeaderActive=true]
[junit4] 2> 59407 INFO (qtp1454865170-491) [n:127.0.0.1:42086__a%2Fac ] o.a.s.h.a.PrepRecoveryOp Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true, onlyIfLeaderActive: true
[junit4] 2> 59408 INFO (qtp1454865170-491) [n:127.0.0.1:42086__a%2Fac ] o.a.s.h.a.PrepRecoveryOp Will wait a max of 183 seconds to see collection1 (shard1 of collection1) have state: recovering
[junit4] 2> 59408 INFO (qtp1454865170-491) [n:127.0.0.1:42086__a%2Fac ] o.a.s.h.a.PrepRecoveryOp In WaitForState(recovering): collection=collection1, shard=shard1, thisCore=collection1, leaderDoesNotNeedRecovery=false, isLeader? true, live=true, checkLive=true, currentState=down, localState=active, nodeName=127.0.0.1:45762__a%2Fac, coreNodeName=core_node4, onlyIfActiveCheckResult=false, nodeProps: core_node4:{"core":"collection1","base_url":"http://127.0.0.1:45762/_a/ac","node_name":"127.0.0.1:45762__a%2Fac","state":"down"}
[junit4] 2> 59633 INFO (T
[...truncated too long message...]
s.c.Overseer Overseer (id=97928818953486354-127.0.0.1:45996__a%2Fac-n_0000000004) starting
[junit4] 2> 866039 INFO (zkCallback-285-thread-4-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json] for collection [collection1] has occurred - updating... (live nodes size: [1])
[junit4] 2> 866992 INFO (zkCallback-285-thread-2-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:45996/_a/ac/collection1/
[junit4] 2> 866992 INFO (zkCallback-285-thread-3-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1_0 r:core_node7 x:collection1_shard1_0_replica0] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:45996/_a/ac/collection1_shard1_0_replica0/
[junit4] 2> 866992 INFO (zkCallback-285-thread-2-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 866992 INFO (zkCallback-285-thread-3-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1_0 r:core_node7 x:collection1_shard1_0_replica0] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 866992 INFO (zkCallback-285-thread-2-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.SyncStrategy http://127.0.0.1:45996/_a/ac/collection1/ has no replicas
[junit4] 2> 866992 INFO (zkCallback-285-thread-3-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1_0 r:core_node7 x:collection1_shard1_0_replica0] o.a.s.c.SyncStrategy http://127.0.0.1:45996/_a/ac/collection1_shard1_0_replica0/ has no replicas
[junit4] 2> 866994 INFO (zkCallback-285-thread-2-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:45996/_a/ac/collection1/ shard1
[junit4] 2> 866994 INFO (zkCallback-285-thread-3-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1_0 r:core_node7 x:collection1_shard1_0_replica0] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:45996/_a/ac/collection1_shard1_0_replica0/ shard1_0
[junit4] 2> 867096 INFO (zkCallback-285-thread-3-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json] for collection [collection1] has occurred - updating... (live nodes size: [1])
[junit4] 2> 867533 WARN (zkCallback-278-thread-1-processing-n:127.0.0.1:37973__a%2Fac) [n:127.0.0.1:37973__a%2Fac ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 867534 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@51359a30{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 867534 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@5e479ac7{/_a/ac,null,UNAVAILABLE}
[junit4] 2> 867535 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ChaosMonkey monkey: stop shard! 45996
[junit4] 2> 867535 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1624428704
[junit4] 2> 867535 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node
[junit4] 2> 867535 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jvm
[junit4] 2> 867535 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.jetty
[junit4] 2> 867536 INFO (coreCloseExecutor-961-thread-1) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@43b8c279
[junit4] 2> 867536 INFO (coreCloseExecutor-961-thread-2) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1_0 r:core_node7 x:collection1_shard1_0_replica0] o.a.s.c.SolrCore [collection1_shard1_0_replica0] CLOSING SolrCore org.apache.solr.core.SolrCore@4c055d81
[junit4] 2> 867580 INFO (coreCloseExecutor-961-thread-2) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1_0 r:core_node7 x:collection1_shard1_0_replica0] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.collection1.shard1_0.replica0
[junit4] 2> 867583 INFO (coreCloseExecutor-961-thread-1) [n:127.0.0.1:45996__a%2Fac c:collection1 s:shard1 r:core_node4 x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.collection1
[junit4] 2> 867584 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.Overseer Overseer (id=97928818953486354-127.0.0.1:45996__a%2Fac-n_0000000004) closing
[junit4] 2> 867584 INFO (OverseerStateUpdate-97928818953486354-127.0.0.1:45996__a%2Fac-n_0000000004) [n:127.0.0.1:45996__a%2Fac ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:45996__a%2Fac
[junit4] 2> 867596 WARN (zkCallback-285-thread-3-processing-n:127.0.0.1:45996__a%2Fac) [n:127.0.0.1:45996__a%2Fac ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 867597 INFO (zkCallback-260-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0)
[junit4] 2> 867600 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@ed0d8b6{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 867600 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@4d5ede3d{/_a/ac,null,UNAVAILABLE}
[junit4] 2> 867601 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ChaosMonkey monkey: stop shard! 46693
[junit4] 2> 867601 ERROR (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 867602 INFO (TEST-ShardSplitTest.testSplitAfterFailedSplit-seed#[E80FC51C3CA9E5F9]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:40188 40188
[junit4] 2> 867625 INFO (Thread-427) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:40188 40188
[junit4] 2> 867626 WARN (Thread-427) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/aliases.json
[junit4] 2> 6 /solr/clusterprops.json
[junit4] 2> 5 /solr/security.json
[junit4] 2> 5 /solr/configs/conf1
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/clusterstate.json
[junit4] 2> 4 /solr/collections/collection1/state.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/live_nodes
[junit4] 2> 6 /solr/collections
[junit4] 2> 4 /solr/overseer/queue
[junit4] 2> 4 /solr/overseer/collection-queue-work
[junit4] 2> 2 /solr/overseer/queue-work
[junit4] 2>
[junit4] 2> 867632 INFO (SUITE-ShardSplitTest-seed#[E80FC51C3CA9E5F9]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-6.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.ShardSplitTest_E80FC51C3CA9E5F9-001
[junit4] 2> May 08, 2017 8:27:09 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 3 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62): {rnd_b=FST50, shard_s=PostingsFormat(name=Direct), n_ti=PostingsFormat(name=Direct), a_t=PostingsFormat(name=Direct), a_i=FST50, id=FST50}, docValues:{rnd_b=DocValuesFormat(name=Memory), shard_s=DocValuesFormat(name=Asserting), _version_=DocValuesFormat(name=Asserting), n_ti=DocValuesFormat(name=Asserting), a_t=DocValuesFormat(name=Asserting), a_i=DocValuesFormat(name=Memory), id=DocValuesFormat(name=Memory)}, maxPointsInLeafNode=2028, maxMBSortInHeap=6.150736461104758, sim=RandomSimilarity(queryNorm=false,coord=yes): {}, locale=id, timezone=America/Araguaina
[junit4] 2> NOTE: Linux 4.4.0-75-generic amd64/Oracle Corporation 1.8.0_131 (64-bit)/cpus=12,threads=1,free=217892888,total=518979584
[junit4] 2> NOTE: All tests run in this JVM: [PluginInfoTest, HdfsRestartWhileUpdatingTest, TestObjectReleaseTracker, DistributedFacetPivotLongTailTest, BadIndexSchemaTest, TestEmbeddedSolrServerSchemaAPI, ShowFileRequestHandlerTest, JSONWriterTest, FieldAnalysisRequestHandlerTest, PeerSyncWithIndexFingerprintCachingTest, DirectUpdateHandlerOptimizeTest, TestZkChroot, ShardSplitTest]
[junit4] Completed [228/711 (1!)] on J2 in 817.83s, 5 tests, 1 failure <<< FAILURES!
[...truncated 44990 lines...]