From dev-return-310347-archive-asf-public=cust-asf.ponee.io@lucene.apache.org Thu Feb 1 10:37:14 2018 Return-Path: X-Original-To: archive-asf-public@eu.ponee.io Delivered-To: archive-asf-public@eu.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by mx-eu-01.ponee.io (Postfix) with ESMTP id EAC8C180652 for ; Thu, 1 Feb 2018 10:37:13 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id DA6BC160C56; Thu, 1 Feb 2018 09:37:13 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id 3EE19160C26 for ; Thu, 1 Feb 2018 10:37:11 +0100 (CET) Received: (qmail 66532 invoked by uid 500); 1 Feb 2018 09:37:05 -0000 Mailing-List: contact dev-help@lucene.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@lucene.apache.org Delivered-To: mailing list dev@lucene.apache.org Received: (qmail 66508 invoked by uid 99); 1 Feb 2018 09:37:04 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd3-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 01 Feb 2018 09:37:04 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd3-us-west.apache.org (ASF Mail Server at spamd3-us-west.apache.org) with ESMTP id 4ECCC19A753 for ; Thu, 1 Feb 2018 09:37:04 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd3-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -0.3 X-Spam-Level: X-Spam-Status: No, score=-0.3 tagged_above=-999 required=6.31 tests=[KAM_BADIPHTTP=2, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, WEIRD_PORT=0.001] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd3-us-west.apache.org [10.40.0.10]) (amavisd-new, port 10024) with ESMTP id pU9boOQ45DNI for ; Thu, 1 Feb 2018 09:36:47 +0000 (UTC) Received: from serv1.sd-datasolutions.de (serv1.sd-datasolutions.de [88.99.242.108]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id 475D45F2A9 for ; Thu, 1 Feb 2018 09:36:47 +0000 (UTC) Received: from serv1 (ip6-localhost [IPv6:::1]) by serv1.sd-datasolutions.de (Postfix) with ESMTP id 2D7FC10805A9 for ; Thu, 1 Feb 2018 09:36:44 +0000 (UTC) Date: Thu, 1 Feb 2018 09:35:08 +0000 (UTC) From: Policeman Jenkins Server To: dev@lucene.apache.org Message-ID: <1429286646.39.1517477804187.JavaMail.jenkins@serv1.sd-datasolutions.de> In-Reply-To: <1059980154.15.1517440280989.JavaMail.jenkins@serv1.sd-datasolutions.de> References: <1059980154.15.1517440280989.JavaMail.jenkins@serv1.sd-datasolutions.de> Subject: [JENKINS] Lucene-Solr-master-MacOSX (64bit/jdk-9) - Build # 4418 - Still Unstable! MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----=_Part_38_1588760094.1517477804148" X-Jenkins-Job: Lucene-Solr-master-MacOSX X-Jenkins-Result: UNSTABLE ------=_Part_38_1588760094.1517477804148 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Build: https://jenkins.thetaphi.de/job/Lucene-Solr-master-MacOSX/4418/ Java: 64bit/jdk-9 -XX:+UseCompressedOops -XX:+UseG1GC 4 tests failed. FAILED: org.apache.solr.cloud.TestTlogReplica.testRecovery Error Message: Can not find doc 8 in http://127.0.0.1:50137/solr Stack Trace: java.lang.AssertionError: Can not find doc 8 in http://127.0.0.1:50137/solr =09at __randomizedtesting.SeedInfo.seed([624230E011B6037C:A3B2494C3CE6C9DB]= :0) =09at org.junit.Assert.fail(Assert.java:93) =09at org.junit.Assert.assertTrue(Assert.java:43) =09at org.junit.Assert.assertNotNull(Assert.java:526) =09at org.apache.solr.cloud.TestTlogReplica.checkRTG(TestTlogReplica.java:8= 85) =09at org.apache.solr.cloud.TestTlogReplica.testRecovery(TestTlogReplica.ja= va:599) =09at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Nativ= e Method) =09at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Native= MethodAccessorImpl.java:62) =09at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(De= legatingMethodAccessorImpl.java:43) =09at java.base/java.lang.reflect.Method.invoke(Method.java:564) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(Randomized= Runner.java:1737) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(Random= izedRunner.java:934) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(Random= izedRunner.java:970) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(Rando= mizedRunner.java:984) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:57) =09at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRu= leSetupTeardownChained.java:49) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:45) =09at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleT= hreadAndTestName.java:48) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:64) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:47) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:368) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTa= sk(ThreadLeakControl.java:817) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(Threa= dLeakControl.java:468) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(Ran= domizedRunner.java:943) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(Random= izedRunner.java:829) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(Random= izedRunner.java:879) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(Random= izedRunner.java:890) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:57) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:45) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStor= eClassName.java:41) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRule= AssertionsRequired.java:53) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:47) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:64) =09at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIg= noreTestSuites.java:54) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:368) =09at java.base/java.lang.Thread.run(Thread.java:844) FAILED: org.apache.solr.cloud.autoscaling.ComputePlanActionTest.testNodeWi= thMultipleReplicasLost Error Message: The operations computed by ComputePlanAction should not be null SolrClientN= odeStateProvider.DEBUG{AFTER_ACTION=3D[compute_plan, null], BEFORE_ACTION= =3D[compute_plan, null]} Stack Trace: java.lang.AssertionError: The operations computed by ComputePlanAction shou= ld not be null SolrClientNodeStateProvider.DEBUG{AFTER_ACTION=3D[compute_pl= an, null], BEFORE_ACTION=3D[compute_plan, null]} =09at __randomizedtesting.SeedInfo.seed([624230E011B6037C:5282D16299C4E220]= :0) =09at org.junit.Assert.fail(Assert.java:93) =09at org.junit.Assert.assertTrue(Assert.java:43) =09at org.junit.Assert.assertNotNull(Assert.java:526) =09at org.apache.solr.cloud.autoscaling.ComputePlanActionTest.testNodeWithM= ultipleReplicasLost(ComputePlanActionTest.java:291) =09at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Nativ= e Method) =09at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Native= MethodAccessorImpl.java:62) =09at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(De= legatingMethodAccessorImpl.java:43) =09at java.base/java.lang.reflect.Method.invoke(Method.java:564) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(Randomized= Runner.java:1737) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(Random= izedRunner.java:934) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(Random= izedRunner.java:970) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(Rando= mizedRunner.java:984) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:57) =09at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRu= leSetupTeardownChained.java:49) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:45) =09at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleT= hreadAndTestName.java:48) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:64) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:47) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:368) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTa= sk(ThreadLeakControl.java:817) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(Threa= dLeakControl.java:468) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(Ran= domizedRunner.java:943) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(Random= izedRunner.java:829) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(Random= izedRunner.java:879) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(Random= izedRunner.java:890) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:57) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:45) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStor= eClassName.java:41) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRule= AssertionsRequired.java:53) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:47) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:64) =09at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIg= noreTestSuites.java:54) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:368) =09at java.base/java.lang.Thread.run(Thread.java:844) FAILED: org.apache.solr.cloud.autoscaling.TriggerIntegrationTest.testNodeA= ddedTriggerRestoreState Error Message: The trigger did not fire at all Stack Trace: java.lang.AssertionError: The trigger did not fire at all =09at __randomizedtesting.SeedInfo.seed([624230E011B6037C:EA7FB99F2B76E2D1]= :0) =09at org.junit.Assert.fail(Assert.java:93) =09at org.junit.Assert.assertTrue(Assert.java:43) =09at org.apache.solr.cloud.autoscaling.TriggerIntegrationTest.testNodeAdde= dTriggerRestoreState(TriggerIntegrationTest.java:426) =09at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Nativ= e Method) =09at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Native= MethodAccessorImpl.java:62) =09at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(De= legatingMethodAccessorImpl.java:43) =09at java.base/java.lang.reflect.Method.invoke(Method.java:564) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(Randomized= Runner.java:1737) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(Random= izedRunner.java:934) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(Random= izedRunner.java:970) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(Rando= mizedRunner.java:984) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:57) =09at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRu= leSetupTeardownChained.java:49) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:45) =09at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleT= hreadAndTestName.java:48) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:64) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:47) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:368) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTa= sk(ThreadLeakControl.java:817) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(Threa= dLeakControl.java:468) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(Ran= domizedRunner.java:943) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(Random= izedRunner.java:829) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(Random= izedRunner.java:879) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(Random= izedRunner.java:890) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:57) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:45) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStor= eClassName.java:41) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRule= AssertionsRequired.java:53) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:47) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:64) =09at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIg= noreTestSuites.java:54) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:368) =09at java.base/java.lang.Thread.run(Thread.java:844) FAILED: org.apache.solr.cloud.autoscaling.TriggerIntegrationTest.testNodeL= ostTrigger Error Message: Stack Trace: java.lang.AssertionError =09at __randomizedtesting.SeedInfo.seed([624230E011B6037C:66BC99F22B7C81E6]= :0) =09at org.junit.Assert.fail(Assert.java:92) =09at org.junit.Assert.assertTrue(Assert.java:43) =09at org.junit.Assert.assertTrue(Assert.java:54) =09at org.apache.solr.cloud.autoscaling.TriggerIntegrationTest.testNodeLost= Trigger(TriggerIntegrationTest.java:521) =09at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Nativ= e Method) =09at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(Native= MethodAccessorImpl.java:62) =09at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(De= legatingMethodAccessorImpl.java:43) =09at java.base/java.lang.reflect.Method.invoke(Method.java:564) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(Randomized= Runner.java:1737) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(Random= izedRunner.java:934) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(Random= izedRunner.java:970) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(Rando= mizedRunner.java:984) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:57) =09at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRu= leSetupTeardownChained.java:49) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:45) =09at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleT= hreadAndTestName.java:48) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:64) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:47) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:368) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTa= sk(ThreadLeakControl.java:817) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(Threa= dLeakControl.java:468) =09at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(Ran= domizedRunner.java:943) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(Random= izedRunner.java:829) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(Random= izedRunner.java:879) =09at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(Random= izedRunner.java:890) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$= 1.evaluate(SystemPropertiesRestoreRule.java:57) =09at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBef= oreAfterRule.java:45) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStor= eClassName.java:41) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) =09at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMeth= odsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRule= AssertionsRequired.java:53) =09at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFai= lure.java:47) =09at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(Test= RuleIgnoreAfterMaxFailures.java:64) =09at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIg= noreTestSuites.java:54) =09at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(St= atementAdapter.java:36) =09at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.= run(ThreadLeakControl.java:368) =09at java.base/java.lang.Thread.run(Thread.java:844) Build Log: [...truncated 13465 lines...] [junit4] Suite: org.apache.solr.cloud.TestTlogReplica [junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-mas= ter-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.TestTlogReplica_624= 230E011B6037C-001/init-core-data-001 [junit4] 2> 2720679 WARN (SUITE-TestTlogReplica-seed#[624230E011B6037= C]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=3D1= numCloses=3D1 [junit4] 2> 2720679 INFO (SUITE-TestTlogReplica-seed#[624230E011B6037= C]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SY= SPROP=3Dtrue) w/NUMERIC_DOCVALUES_SYSPROP=3Dtrue [junit4] 2> 2720680 INFO (SUITE-TestTlogReplica-seed#[624230E011B6037= C]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAut= h (false) via: @org.apache.solr.util.RandomizeSSL(reason=3D"", value=3D0.0/= 0.0, ssl=3D0.0/0.0, clientAuth=3D0.0/0.0) w/ MAC_OS_X supressed clientAuth [junit4] 2> 2720680 INFO (SUITE-TestTlogReplica-seed#[624230E011B6037= C]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.sol= r.allowed.securerandom=3Dnull & java.security.egd=3Dfile:/dev/./urandom [junit4] 2> 2720680 INFO (SUITE-TestTlogReplica-seed#[624230E011B6037= C]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 server= s in /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-cor= e/test/J0/temp/solr.cloud.TestTlogReplica_624230E011B6037C-001/tempDir-001 [junit4] 2> 2720680 INFO (SUITE-TestTlogReplica-seed#[624230E011B6037= C]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 2720681 INFO (Thread-4339) [ ] o.a.s.c.ZkTestServer cl= ient port:0.0.0.0/0.0.0.0:0 [junit4] 2> 2720681 INFO (Thread-4339) [ ] o.a.s.c.ZkTestServer St= arting server [junit4] 2> 2720683 ERROR (Thread-4339) [ ] o.a.z.s.ZooKeeperServer= ZKShutdownHandler is not registered, so ZooKeeper server won't take any ac= tion on ERROR or SHUTDOWN server state changes [junit4] 2> 2720786 INFO (SUITE-TestTlogReplica-seed#[624230E011B6037= C]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:50135 [junit4] 2> 2720798 INFO (zkConnectionManagerCallback-10156-thread-1)= [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 2720803 INFO (jetty-launcher-10153-thread-2) [ ] o.e.j= .s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T16:27:37-05:00= , git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8 [junit4] 2> 2720803 INFO (jetty-launcher-10153-thread-1) [ ] o.e.j= .s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T16:27:37-05:00= , git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8 [junit4] 2> 2720804 INFO (jetty-launcher-10153-thread-2) [ ] o.e.j= .s.session DefaultSessionIdManager workerName=3Dnode0 [junit4] 2> 2720804 INFO (jetty-launcher-10153-thread-2) [ ] o.e.j= .s.session No SessionScavenger set, using defaults [junit4] 2> 2720804 INFO (jetty-launcher-10153-thread-2) [ ] o.e.j= .s.session Scavenging every 600000ms [junit4] 2> 2720805 INFO (jetty-launcher-10153-thread-2) [ ] o.e.j= .s.h.ContextHandler Started o.e.j.s.ServletContextHandler@332bcb7a{/solr,nu= ll,AVAILABLE} [junit4] 2> 2720805 INFO (jetty-launcher-10153-thread-1) [ ] o.e.j= .s.session DefaultSessionIdManager workerName=3Dnode0 [junit4] 2> 2720805 INFO (jetty-launcher-10153-thread-1) [ ] o.e.j= .s.session No SessionScavenger set, using defaults [junit4] 2> 2720805 INFO (jetty-launcher-10153-thread-1) [ ] o.e.j= .s.session Scavenging every 660000ms [junit4] 2> 2720805 INFO (jetty-launcher-10153-thread-2) [ ] o.e.j= .s.AbstractConnector Started ServerConnector@4667b60{HTTP/1.1,[http/1.1]}{1= 27.0.0.1:50137} [junit4] 2> 2720805 INFO (jetty-launcher-10153-thread-2) [ ] o.e.j= .s.Server Started @2722932ms [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-2) [ ] o.a.s= .c.s.e.JettySolrRunner Jetty properties: {hostContext=3D/solr, hostPort=3D5= 0137} [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-1) [ ] o.e.j= .s.h.ContextHandler Started o.e.j.s.ServletContextHandler@7cbf5e07{/solr,nu= ll,AVAILABLE} [junit4] 2> 2720806 ERROR (jetty-launcher-10153-thread-2) [ ] o.a.s= .u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be mis= sing or incomplete. [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-1) [ ] o.e.j= .s.AbstractConnector Started ServerConnector@1e763009{HTTP/1.1,[http/1.1]}{= 127.0.0.1:50138} [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-1) [ ] o.e.j= .s.Server Started @2722933ms [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-1) [ ] o.a.s= .c.s.e.JettySolrRunner Jetty properties: {hostContext=3D/solr, hostPort=3D5= 0138} [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-2) [ ] o.a.s= .s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0= .0 [junit4] 2> 2720806 ERROR (jetty-launcher-10153-thread-1) [ ] o.a.s= .u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be mis= sing or incomplete. [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-2) [ ] o.a.s= .s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-2) [ ] o.a.s= .s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-2) [ ] o.a.s= .s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-02-01T08:59:46.537= 709Z [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-1) [ ] o.a.s= .s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0= .0 [junit4] 2> 2720806 INFO (jetty-launcher-10153-thread-1) [ ] o.a.s= .s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 2720807 INFO (jetty-launcher-10153-thread-1) [ ] o.a.s= .s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 2720807 INFO (jetty-launcher-10153-thread-1) [ ] o.a.s= .s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-02-01T08:59:46.538= 060Z [junit4] 2> 2720808 INFO (zkConnectionManagerCallback-10158-thread-1)= [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 2720808 INFO (zkConnectionManagerCallback-10160-thread-1)= [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 2720809 INFO (jetty-launcher-10153-thread-2) [ ] o.a.s= .s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 2720809 INFO (jetty-launcher-10153-thread-1) [ ] o.a.s= .s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 2720826 INFO (jetty-launcher-10153-thread-1) [ ] o.a.s= .c.ZkContainer Zookeeper client=3D127.0.0.1:50135/solr [junit4] 2> 2720826 INFO (jetty-launcher-10153-thread-2) [ ] o.a.s= .c.ZkContainer Zookeeper client=3D127.0.0.1:50135/solr [junit4] 2> 2720827 INFO (zkConnectionManagerCallback-10165-thread-1)= [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 2720828 INFO (zkConnectionManagerCallback-10168-thread-1)= [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 2720830 INFO (zkConnectionManagerCallback-10170-thread-1-= processing-n:127.0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.C= onnectionManager zkClient has connected [junit4] 2> 2720831 INFO (zkConnectionManagerCallback-10172-thread-1-= processing-n:127.0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.C= onnectionManager zkClient has connected [junit4] 2> 2720976 INFO (jetty-launcher-10153-thread-2) [n:127.0.0.1= :50137_solr ] o.a.s.c.Overseer Overseer (id=3Dnull) closing [junit4] 2> 2720977 INFO (jetty-launcher-10153-thread-2) [n:127.0.0.1= :50137_solr ] o.a.s.c.OverseerElectionContext I am going to be the leade= r 127.0.0.1:50137_solr [junit4] 2> 2720978 INFO (jetty-launcher-10153-thread-1) [n:127.0.0.1= :50138_solr ] o.a.s.c.Overseer Overseer (id=3Dnull) closing [junit4] 2> 2720978 INFO (jetty-launcher-10153-thread-2) [n:127.0.0.1= :50137_solr ] o.a.s.c.Overseer Overseer (id=3D72122435697967110-127.0.0.= 1:50137_solr-n_0000000000) starting [junit4] 2> 2720979 INFO (jetty-launcher-10153-thread-1) [n:127.0.0.1= :50138_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/l= ive_nodes/127.0.0.1:50138_solr [junit4] 2> 2720981 INFO (zkCallback-10171-thread-1-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader Upda= ted live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 2720981 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader Upda= ted live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 2720993 INFO (jetty-launcher-10153-thread-2) [n:127.0.0.1= :50137_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/l= ive_nodes/127.0.0.1:50137_solr [junit4] 2> 2720995 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader Upda= ted live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 2720995 INFO (zkCallback-10171-thread-1-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader Upda= ted live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 2721046 INFO (jetty-launcher-10153-thread-1) [n:127.0.0.1= :50138_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_50138.s= olr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver= .JmxMBeanServer@3d8cbbcc [junit4] 2> 2721057 INFO (jetty-launcher-10153-thread-1) [n:127.0.0.1= :50138_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_50138.s= olr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.J= mxMBeanServer@3d8cbbcc [junit4] 2> 2721057 INFO (jetty-launcher-10153-thread-1) [n:127.0.0.1= :50138_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_50138.s= olr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserv= er.JmxMBeanServer@3d8cbbcc [junit4] 2> 2721057 INFO (jetty-launcher-10153-thread-2) [n:127.0.0.1= :50137_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_50137.s= olr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver= .JmxMBeanServer@3d8cbbcc [junit4] 2> 2721058 INFO (jetty-launcher-10153-thread-1) [n:127.0.0.1= :50138_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions und= erneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-= core/test/J0/temp/solr.cloud.TestTlogReplica_624230E011B6037C-001/tempDir-0= 01/node1/. [junit4] 2> 2721066 INFO (jetty-launcher-10153-thread-2) [n:127.0.0.1= :50137_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_50137.s= olr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.J= mxMBeanServer@3d8cbbcc [junit4] 2> 2721066 INFO (jetty-launcher-10153-thread-2) [n:127.0.0.1= :50137_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_50137.s= olr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserv= er.JmxMBeanServer@3d8cbbcc [junit4] 2> 2721067 INFO (jetty-launcher-10153-thread-2) [n:127.0.0.1= :50137_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions und= erneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-= core/test/J0/temp/solr.cloud.TestTlogReplica_624230E011B6037C-001/tempDir-0= 01/node2/. [junit4] 2> 2721099 INFO (zkConnectionManagerCallback-10178-thread-1)= [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 2721103 INFO (zkConnectionManagerCallback-10182-thread-1)= [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 2721105 INFO (SUITE-TestTlogReplica-seed#[624230E011B6037= C]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper= ... (0) -> (2) [junit4] 2> 2721107 INFO (SUITE-TestTlogReplica-seed#[624230E011B6037= C]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0= .0.1:50135/solr ready [junit4] 2> 2721114 INFO (SUITE-TestTlogReplica-seed#[624230E011B6037= C]-worker) [ ] o.a.s.c.TestTlogReplica Using legacyCloud?: false [junit4] 2> 2721117 INFO (qtp1387007808-31122) [n:127.0.0.1:50137_sol= r ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :clusterprop = with params val=3Dfalse&name=3DlegacyCloud&action=3DCLUSTERPROP&wt=3Djavabi= n&version=3D2 and sendToOCPQueue=3Dtrue [junit4] 2> 2721118 INFO (qtp1387007808-31122) [n:127.0.0.1:50137_sol= r ] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/collections= params=3D{val=3Dfalse&name=3DlegacyCloud&action=3DCLUSTERPROP&wt=3Djavabin= &version=3D2} status=3D0 QTime=3D1 [junit4] 2> 2721129 INFO (TEST-TestTlogReplica.testAddDocs-seed#[6242= 30E011B6037C]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testAddDocs [junit4] 2> 2721131 INFO (qtp1387007808-31124) [n:127.0.0.1:50137_sol= r ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with = params pullReplicas=3D0&replicationFactor=3D0&collection.configName=3Dconf&= maxShardsPerNode=3D100&name=3Dtlog_replica_test_add_docs&nrtReplicas=3D0&ac= tion=3DCREATE&numShards=3D1&tlogReplicas=3D1&wt=3Djavabin&version=3D2 and s= endToOCPQueue=3Dtrue [junit4] 2> 2721135 INFO (OverseerThreadFactory-10289-thread-1-proces= sing-n:127.0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.a.c.Creat= eCollectionCmd Create collection tlog_replica_test_add_docs [junit4] 2> 2721254 INFO (OverseerStateUpdate-72122435697967110-127.0= .0.1:50137_solr-n_0000000000) [n:127.0.0.1:50137_solr ] o.a.s.c.o.SliceM= utator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_add_docs", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"tlog_replica_test_add_docs_shard1_replica_t1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:50138/solr", [junit4] 2> "type":"TLOG", [junit4] 2> "waitForFinalState":"false"}=20 [junit4] 2> 2721470 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= ] o.a.s.h.a.CoreAdminOperation core create command qt=3D/admin/cores&co= reNodeName=3Dcore_node2&collection.configName=3Dconf&newCollection=3Dtrue&n= ame=3Dtlog_replica_test_add_docs_shard1_replica_t1&action=3DCREATE&numShard= s=3D1&collection=3Dtlog_replica_test_add_docs&shard=3Dshard1&wt=3Djavabin&v= ersion=3D2&replicaType=3DTLOG [junit4] 2> 2721470 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for = 2147483647 transient cores [junit4] 2> 2721576 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_add_docs/state.json] for collection [tl= og_replica_test_add_docs] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2721577 INFO (zkCallback-10169-thread-2-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_add_docs/state.json] for collection [tl= og_replica_test_add_docs] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2722487 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.= 0 [junit4] 2> 2722492 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.s.IndexSchema [tlog_replica_test_add_docs_sh= ard1_replica_t1] Schema name=3Dminimal [junit4] 2> 2722493 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with= uniqueid field id [junit4] 2> 2722493 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.CoreContainer Creating SolrCore 'tlog_repl= ica_test_add_docs_shard1_replica_t1' using configuration from collection tl= og_replica_test_add_docs, trusted=3Dtrue [junit4] 2> 2722493 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr= _50138.solr.core.tlog_replica_test_add_docs.shard1.replica_t1' (registry 's= olr.core.tlog_replica_test_add_docs.shard1.replica_t1') enabled at server: = com.sun.jmx.mbeanserver.JmxMBeanServer@3d8cbbcc [junit4] 2> 2722493 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 2722493 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.SolrCore [[tlog_replica_test_add_docs_shar= d1_replica_t1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-S= olr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.TestTlogRepl= ica_624230E011B6037C-001/tempDir-001/node1/tlog_replica_test_add_docs_shard= 1_replica_t1], dataDir=3D[/Users/jenkins/workspace/Lucene-Solr-master-MacOS= X/solr/build/solr-core/test/J0/temp/solr.cloud.TestTlogReplica_624230E011B6= 037C-001/tempDir-001/node1/./tlog_replica_test_add_docs_shard1_replica_t1/d= ata/] [junit4] 2> 2722537 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.u.UpdateHandler Using UpdateLog implementati= on: org.apache.solr.update.UpdateLog [junit4] 2> 2722537 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= =3Dnull defaultSyncLevel=3DFLUSH numRecordsToKeep=3D100 maxNumLogsToKeep=3D= 10 numVersionBuckets=3D65536 [junit4] 2> 2722538 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 2722538 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 2722539 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5ed985= a3[tlog_replica_test_add_docs_shard1_replica_t1] main] [junit4] 2> 2722541 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.r.ManagedResourceStorage Configured ZooKeepe= rStorageIO with znodeBase: /configs/conf [junit4] 2> 2722541 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.r.ManagedResourceStorage Loaded null at path= _rest_managed.json using ZooKeeperStorageIO:path=3D/configs/conf [junit4] 2> 2722542 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.h.ReplicationHandler Commits will be reserve= d for 10000ms. [junit4] 2> 2722542 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.u.UpdateLog Could not find max version in in= dex or recent updates, using new clock 1591188482448949248 [junit4] 2> 2722543 INFO (searcherExecutor-10294-thread-1-processing-= n:127.0.0.1:50138_solr x:tlog_replica_test_add_docs_shard1_replica_t1 s:sha= rd1 c:tlog_replica_test_add_docs r:core_node2) [n:127.0.0.1:50138_solr c:tl= og_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add_docs= _shard1_replica_t1] o.a.s.c.SolrCore [tlog_replica_test_add_docs_shard1_rep= lica_t1] Registered new searcher Searcher@5ed985a3[tlog_replica_test_add_do= cs_shard1_replica_t1] main{ExitableDirectoryReader(UninvertingDirectoryRead= er())} [junit4] 2> 2722553 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.ShardLeaderElectionContext Enough replicas= found to continue. [junit4] 2> 2722553 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.ShardLeaderElectionContext I may be the ne= w leader - try and sync [junit4] 2> 2722553 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.SyncStrategy Sync replicas to http://127.0= .0.1:50138/solr/tlog_replica_test_add_docs_shard1_replica_t1/ [junit4] 2> 2722553 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.SyncStrategy Sync Success - now sync repli= cas to me [junit4] 2> 2722553 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.SyncStrategy http://127.0.0.1:50138/solr/t= log_replica_test_add_docs_shard1_replica_t1/ has no replicas [junit4] 2> 2722553 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.ShardLeaderElectionContext Found all repli= cas participating in election, clear LIR [junit4] 2> 2722553 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.ZkController tlog_replica_test_add_docs_sh= ard1_replica_t1 stopping background replication from leader [junit4] 2> 2722558 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.ShardLeaderElectionContext I am the new le= ader: http://127.0.0.1:50138/solr/tlog_replica_test_add_docs_shard1_replica= _t1/ shard1 [junit4] 2> 2722669 INFO (zkCallback-10169-thread-2-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_add_docs/state.json] for collection [tl= og_replica_test_add_docs] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2722669 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_add_docs/state.json] for collection [tl= og_replica_test_add_docs] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2722672 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.ZkController I am the leader, no recovery = necessary [junit4] 2> 2722675 INFO (qtp469824676-31126) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path=3D= /admin/cores params=3D{qt=3D/admin/cores&coreNodeName=3Dcore_node2&collecti= on.configName=3Dconf&newCollection=3Dtrue&name=3Dtlog_replica_test_add_docs= _shard1_replica_t1&action=3DCREATE&numShards=3D1&collection=3Dtlog_replica_= test_add_docs&shard=3Dshard1&wt=3Djavabin&version=3D2&replicaType=3DTLOG} s= tatus=3D0 QTime=3D1205 [junit4] 2> 2722679 INFO (qtp1387007808-31124) [n:127.0.0.1:50137_sol= r ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active fo= r at most 30 seconds. Check all shard replicas [junit4] 2> 2722784 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_add_docs/state.json] for collection [tl= og_replica_test_add_docs] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2722784 INFO (zkCallback-10169-thread-2-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_add_docs/state.json] for collection [tl= og_replica_test_add_docs] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2723147 INFO (OverseerCollectionConfigSetProcessor-721224= 35697967110-127.0.0.1:50137_solr-n_0000000000) [n:127.0.0.1:50137_solr ]= o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-wor= k/qnr-0000000000 doesn't exist. Requestor may have disconnected from ZooKe= eper [junit4] 2> 2723690 INFO (qtp1387007808-31124) [n:127.0.0.1:50137_sol= r ] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/collections= params=3D{pullReplicas=3D0&replicationFactor=3D0&collection.configName=3Dc= onf&maxShardsPerNode=3D100&name=3Dtlog_replica_test_add_docs&nrtReplicas=3D= 0&action=3DCREATE&numShards=3D1&tlogReplicas=3D1&wt=3Djavabin&version=3D2} = status=3D0 QTime=3D2559 [junit4] 2> 2723696 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.u.p.LogUpdateProcessorFactory [tlog_replica_= test_add_docs_shard1_replica_t1] webapp=3D/solr path=3D/update params=3D{w= t=3Djavabin&version=3D2}{add=3D[1 (1591188483657957376)]} 0 1 [junit4] 2> 2723697 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.u.DirectUpdateHandler2 start commit{_version= _=3D1591188483660054528,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher= =3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 2723697 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.u.SolrIndexWriter Calling setCommitData with= IW:org.apache.solr.update.SolrIndexWriter@38c70f4d commitCommandVersion:15= 91188483660054528 [junit4] 2> 2723700 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6ee5ca= a7[tlog_replica_test_add_docs_shard1_replica_t1] main] [junit4] 2> 2723701 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 2723702 INFO (searcherExecutor-10294-thread-1-processing-= n:127.0.0.1:50138_solr x:tlog_replica_test_add_docs_shard1_replica_t1 s:sha= rd1 c:tlog_replica_test_add_docs r:core_node2) [n:127.0.0.1:50138_solr c:tl= og_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add_docs= _shard1_replica_t1] o.a.s.c.SolrCore [tlog_replica_test_add_docs_shard1_rep= lica_t1] Registered new searcher Searcher@6ee5caa7[tlog_replica_test_add_do= cs_shard1_replica_t1] main{ExitableDirectoryReader(UninvertingDirectoryRead= er(Uninverting(_0(8.0.0):C1)))} [junit4] 2> 2723702 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.u.p.LogUpdateProcessorFactory [tlog_replica_= test_add_docs_shard1_replica_t1] webapp=3D/solr path=3D/update params=3D{_= stateVer_=3Dtlog_replica_test_add_docs:4&waitSearcher=3Dtrue&commit=3Dtrue&= softCommit=3Dfalse&wt=3Djavabin&version=3D2}{commit=3D} 0 5 [junit4] 2> 2723704 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.S.Request [tlog_replica_test_add_docs_shar= d1_replica_t1] webapp=3D/solr path=3D/select params=3D{q=3D*:*&wt=3Djavabi= n&version=3D2} hits=3D1 status=3D0 QTime=3D0 [junit4] 2> 2723706 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.S.Request [tlog_replica_test_add_docs_shar= d1_replica_t1] webapp=3D/solr path=3D/select params=3D{q=3D*:*&wt=3Djavabi= n&version=3D2} hits=3D1 status=3D0 QTime=3D0 [junit4] 2> 2723711 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_add_docs s:shard1 r:core_node2 x:tlog_replica_test_add= _docs_shard1_replica_t1] o.a.s.c.S.Request [tlog_replica_test_add_docs_shar= d1_replica_t1] webapp=3D/solr path=3D/admin/plugins params=3D{qt=3D/admin/= plugins&stats=3Dtrue&wt=3Djavabin&version=3D2} status=3D0 QTime=3D4 [junit4] 2> 2723712 INFO (TEST-TestTlogReplica.testAddDocs-seed#[6242= 30E011B6037C]) [ ] o.a.s.c.TestTlogReplica tearDown deleting collection [junit4] 2> 2723713 INFO (qtp1387007808-31127) [n:127.0.0.1:50137_sol= r ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with = params name=3Dtlog_replica_test_add_docs&action=3DDELETE&wt=3Djavabin&versi= on=3D2 and sendToOCPQueue=3Dtrue [junit4] 2> 2723717 INFO (OverseerThreadFactory-10289-thread-2-proces= sing-n:127.0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.a.c.Overs= eerCollectionMessageHandler Executing Collection Cmd : action=3DUNLOAD&dele= teInstanceDir=3Dtrue&deleteDataDir=3Dtrue [junit4] 2> 2723718 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=3Dsol= r.core.tlog_replica_test_add_docs.shard1.replica_t1, tag=3Dnull [junit4] 2> 2723718 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.r= eporters.SolrJmxReporter@4eaa0f50: rootName =3D solr_50138, domain =3D solr= .core.tlog_replica_test_add_docs.shard1.replica_t1, service url =3D null, a= gent id =3D null] for registry solr.core.tlog_replica_test_add_docs.shard1.= replica_t1 / com.codahale.metrics.MetricRegistry@eb9230d [junit4] 2> 2723728 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= ] o.a.s.c.ZkController tlog_replica_test_add_docs_shard1_replica_t1 sto= pping background replication from leader [junit4] 2> 2723728 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= ] o.a.s.c.SolrCore [tlog_replica_test_add_docs_shard1_replica_t1] CLOS= ING SolrCore org.apache.solr.core.SolrCore@4fae1bb2 [junit4] 2> 2723728 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=3Dsol= r.core.tlog_replica_test_add_docs.shard1.replica_t1, tag=3D1336810418 [junit4] 2> 2723729 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=3Dsol= r.collection.tlog_replica_test_add_docs.shard1.leader, tag=3D1336810418 [junit4] 2> 2723733 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= ] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/cores params= =3D{deleteInstanceDir=3Dtrue&core=3Dtlog_replica_test_add_docs_shard1_repli= ca_t1&qt=3D/admin/cores&deleteDataDir=3Dtrue&action=3DUNLOAD&wt=3Djavabin&v= ersion=3D2} status=3D0 QTime=3D15 [junit4] 2> 2724454 INFO (qtp1387007808-31127) [n:127.0.0.1:50137_sol= r ] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/collections= params=3D{name=3Dtlog_replica_test_add_docs&action=3DDELETE&wt=3Djavabin&v= ersion=3D2} status=3D0 QTime=3D740 [junit4] 2> 2724454 INFO (TEST-TestTlogReplica.testAddDocs-seed#[6242= 30E011B6037C]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testAddDocs [junit4] 2> 2724472 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testRecovery [junit4] 2> 2724473 INFO (qtp1387007808-31124) [n:127.0.0.1:50137_sol= r ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with = params pullReplicas=3D0&replicationFactor=3D0&collection.configName=3Dconf&= maxShardsPerNode=3D100&name=3Dtlog_replica_test_recovery&nrtReplicas=3D0&ac= tion=3DCREATE&numShards=3D1&tlogReplicas=3D2&wt=3Djavabin&version=3D2 and s= endToOCPQueue=3Dtrue [junit4] 2> 2724476 INFO (OverseerThreadFactory-10289-thread-3-proces= sing-n:127.0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.a.c.Creat= eCollectionCmd Create collection tlog_replica_test_recovery [junit4] 2> 2724477 INFO (OverseerCollectionConfigSetProcessor-721224= 35697967110-127.0.0.1:50137_solr-n_0000000000) [n:127.0.0.1:50137_solr ]= o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-wor= k/qnr-0000000002 doesn't exist. Requestor may have disconnected from ZooKe= eper [junit4] 2> 2724691 INFO (OverseerStateUpdate-72122435697967110-127.0= .0.1:50137_solr-n_0000000000) [n:127.0.0.1:50137_solr ] o.a.s.c.o.SliceM= utator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_recovery", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"tlog_replica_test_recovery_shard1_replica_t1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:50137/solr", [junit4] 2> "type":"TLOG", [junit4] 2> "waitForFinalState":"false"}=20 [junit4] 2> 2724695 INFO (OverseerStateUpdate-72122435697967110-127.0= .0.1:50137_solr-n_0000000000) [n:127.0.0.1:50137_solr ] o.a.s.c.o.SliceM= utator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_recovery", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"tlog_replica_test_recovery_shard1_replica_t2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:50138/solr", [junit4] 2> "type":"TLOG", [junit4] 2> "waitForFinalState":"false"}=20 [junit4] 2> 2724909 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= ] o.a.s.h.a.CoreAdminOperation core create command qt=3D/admin/cores&co= reNodeName=3Dcore_node4&collection.configName=3Dconf&newCollection=3Dtrue&n= ame=3Dtlog_replica_test_recovery_shard1_replica_t2&action=3DCREATE&numShard= s=3D1&collection=3Dtlog_replica_test_recovery&shard=3Dshard1&wt=3Djavabin&v= ersion=3D2&replicaType=3DTLOG [junit4] 2> 2724909 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r ] o.a.s.h.a.CoreAdminOperation core create command qt=3D/admin/cores&c= oreNodeName=3Dcore_node3&collection.configName=3Dconf&newCollection=3Dtrue&= name=3Dtlog_replica_test_recovery_shard1_replica_t1&action=3DCREATE&numShar= ds=3D1&collection=3Dtlog_replica_test_recovery&shard=3Dshard1&wt=3Djavabin&= version=3D2&replicaType=3DTLOG [junit4] 2> 2724909 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for= 2147483647 transient cores [junit4] 2> 2725040 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2725040 INFO (zkCallback-10171-thread-1-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2725040 INFO (zkCallback-10169-thread-2-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2725041 INFO (zkCallback-10171-thread-2-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2725954 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.= 0 [junit4] 2> 2725955 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0= .0 [junit4] 2> 2725961 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.s.IndexSchema [tlog_replica_test_recovery_sh= ard1_replica_t2] Schema name=3Dminimal [junit4] 2> 2725963 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with= uniqueid field id [junit4] 2> 2725963 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.CoreContainer Creating SolrCore 'tlog_repl= ica_test_recovery_shard1_replica_t2' using configuration from collection tl= og_replica_test_recovery, trusted=3Dtrue [junit4] 2> 2725963 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr= _50138.solr.core.tlog_replica_test_recovery.shard1.replica_t2' (registry 's= olr.core.tlog_replica_test_recovery.shard1.replica_t2') enabled at server: = com.sun.jmx.mbeanserver.JmxMBeanServer@3d8cbbcc [junit4] 2> 2725963 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 2725963 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.SolrCore [[tlog_replica_test_recovery_shar= d1_replica_t2] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-S= olr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.TestTlogRepl= ica_624230E011B6037C-001/tempDir-001/node1/tlog_replica_test_recovery_shard= 1_replica_t2], dataDir=3D[/Users/jenkins/workspace/Lucene-Solr-master-MacOS= X/solr/build/solr-core/test/J0/temp/solr.cloud.TestTlogReplica_624230E011B6= 037C-001/tempDir-001/node1/./tlog_replica_test_recovery_shard1_replica_t2/d= ata/] [junit4] 2> 2725964 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.s.IndexSchema [tlog_replica_test_recovery_s= hard1_replica_t1] Schema name=3Dminimal [junit4] 2> 2725965 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 wit= h uniqueid field id [junit4] 2> 2725965 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.c.CoreContainer Creating SolrCore 'tlog_rep= lica_test_recovery_shard1_replica_t1' using configuration from collection t= log_replica_test_recovery, trusted=3Dtrue [junit4] 2> 2725966 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'sol= r_50137.solr.core.tlog_replica_test_recovery.shard1.replica_t1' (registry '= solr.core.tlog_replica_test_recovery.shard1.replica_t1') enabled at server:= com.sun.jmx.mbeanserver.JmxMBeanServer@3d8cbbcc [junit4] 2> 2725966 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 2725966 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.c.SolrCore [[tlog_replica_test_recovery_sha= rd1_replica_t1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-= Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.TestTlogRep= lica_624230E011B6037C-001/tempDir-001/node2/tlog_replica_test_recovery_shar= d1_replica_t1], dataDir=3D[/Users/jenkins/workspace/Lucene-Solr-master-MacO= SX/solr/build/solr-core/test/J0/temp/solr.cloud.TestTlogReplica_624230E011B= 6037C-001/tempDir-001/node2/./tlog_replica_test_recovery_shard1_replica_t1/= data/] [junit4] 2> 2726055 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.UpdateHandler Using UpdateLog implementati= on: org.apache.solr.update.UpdateLog [junit4] 2> 2726055 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= =3Dnull defaultSyncLevel=3DFLUSH numRecordsToKeep=3D100 maxNumLogsToKeep=3D= 10 numVersionBuckets=3D65536 [junit4] 2> 2726056 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 2726056 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 2726059 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.u.UpdateHandler Using UpdateLog implementat= ion: org.apache.solr.update.UpdateLog [junit4] 2> 2726059 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= =3Dnull defaultSyncLevel=3DFLUSH numRecordsToKeep=3D100 maxNumLogsToKeep=3D= 10 numVersionBuckets=3D65536 [junit4] 2> 2726063 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 2726063 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 2726089 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.s.SolrIndexSearcher Opening [Searcher@62beb4= a[tlog_replica_test_recovery_shard1_replica_t2] main] [junit4] 2> 2726090 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.r.ManagedResourceStorage Configured ZooKeepe= rStorageIO with znodeBase: /configs/conf [junit4] 2> 2726091 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.r.ManagedResourceStorage Loaded null at path= _rest_managed.json using ZooKeeperStorageIO:path=3D/configs/conf [junit4] 2> 2726091 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.h.ReplicationHandler Commits will be reserve= d for 10000ms. [junit4] 2> 2726092 INFO (searcherExecutor-10299-thread-1-processing-= n:127.0.0.1:50138_solr x:tlog_replica_test_recovery_shard1_replica_t2 s:sha= rd1 c:tlog_replica_test_recovery r:core_node4) [n:127.0.0.1:50138_solr c:tl= og_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_recovery= _shard1_replica_t2] o.a.s.c.SolrCore [tlog_replica_test_recovery_shard1_rep= lica_t2] Registered new searcher Searcher@62beb4a[tlog_replica_test_recover= y_shard1_replica_t2] main{ExitableDirectoryReader(UninvertingDirectoryReade= r())} [junit4] 2> 2726092 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.UpdateLog Could not find max version in in= dex or recent updates, using new clock 1591188486171394048 [junit4] 2> 2726104 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.ShardLeaderElectionContext Waiting until w= e see more replicas up for shard shard1: total=3D2 found=3D1 timeoutin=3D99= 99ms [junit4] 2> 2726105 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.s.SolrIndexSearcher Opening [Searcher@596d8= 3f8[tlog_replica_test_recovery_shard1_replica_t1] main] [junit4] 2> 2726107 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.r.ManagedResourceStorage Configured ZooKeep= erStorageIO with znodeBase: /configs/conf [junit4] 2> 2726109 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.r.ManagedResourceStorage Loaded null at pat= h _rest_managed.json using ZooKeeperStorageIO:path=3D/configs/conf [junit4] 2> 2726110 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.h.ReplicationHandler Commits will be reserv= ed for 10000ms. [junit4] 2> 2726111 INFO (searcherExecutor-10300-thread-1-processing-= n:127.0.0.1:50137_solr x:tlog_replica_test_recovery_shard1_replica_t1 s:sha= rd1 c:tlog_replica_test_recovery r:core_node3) [n:127.0.0.1:50137_solr c:tl= og_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_recovery= _shard1_replica_t1] o.a.s.c.SolrCore [tlog_replica_test_recovery_shard1_rep= lica_t1] Registered new searcher Searcher@596d83f8[tlog_replica_test_recove= ry_shard1_replica_t1] main{ExitableDirectoryReader(UninvertingDirectoryRead= er())} [junit4] 2> 2726111 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.u.UpdateLog Could not find max version in i= ndex or recent updates, using new clock 1591188486191316992 [junit4] 2> 2726555 INFO (zkCallback-10171-thread-3-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2726555 INFO (zkCallback-10169-thread-2-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2726555 INFO (zkCallback-10171-thread-2-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2726555 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2726608 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.ShardLeaderElectionContext Enough replicas= found to continue. [junit4] 2> 2726608 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.ShardLeaderElectionContext I may be the ne= w leader - try and sync [junit4] 2> 2726608 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.SyncStrategy Sync replicas to http://127.0= .0.1:50138/solr/tlog_replica_test_recovery_shard1_replica_t2/ [junit4] 2> 2726609 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.PeerSync PeerSync: core=3Dtlog_replica_tes= t_recovery_shard1_replica_t2 url=3Dhttp://127.0.0.1:50138/solr START replic= as=3D[http://127.0.0.1:50137/solr/tlog_replica_test_recovery_shard1_replica= _t1/] nUpdates=3D100 [junit4] 2> 2726611 INFO (qtp1387007808-31130) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.c.S.Request [tlog_replica_test_recovery_sha= rd1_replica_t1] webapp=3D/solr path=3D/get params=3D{distrib=3Dfalse&qt=3D= /get&fingerprint=3Dfalse&getVersions=3D100&wt=3Djavabin&version=3D2} status= =3D0 QTime=3D0 [junit4] 2> 2726911 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.PeerSync PeerSync: core=3Dtlog_replica_tes= t_recovery_shard1_replica_t2 url=3Dhttp://127.0.0.1:50138/solr DONE. We ha= ve no versions. sync failed. [junit4] 2> 2726911 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.SyncStrategy Leader's attempt to sync with= shard failed, moving to the next candidate [junit4] 2> 2726911 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.ShardLeaderElectionContext We failed sync,= but we have no versions - we can't sync in that case - we were active befo= re, so become leader anyway [junit4] 2> 2726911 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.ShardLeaderElectionContext Found all repli= cas participating in election, clear LIR [junit4] 2> 2726912 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.ZkController tlog_replica_test_recovery_sh= ard1_replica_t2 stopping background replication from leader [junit4] 2> 2726917 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.ShardLeaderElectionContext I am the new le= ader: http://127.0.0.1:50138/solr/tlog_replica_test_recovery_shard1_replica= _t2/ shard1 [junit4] 2> 2727021 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2727021 INFO (zkCallback-10171-thread-2-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2727021 INFO (zkCallback-10171-thread-3-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2727021 INFO (zkCallback-10169-thread-2-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2727070 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.c.ZkController I am the leader, no recovery = necessary [junit4] 2> 2727071 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path=3D= /admin/cores params=3D{qt=3D/admin/cores&coreNodeName=3Dcore_node4&collecti= on.configName=3Dconf&newCollection=3Dtrue&name=3Dtlog_replica_test_recovery= _shard1_replica_t2&action=3DCREATE&numShards=3D1&collection=3Dtlog_replica_= test_recovery&shard=3Dshard1&wt=3Djavabin&version=3D2&replicaType=3DTLOG} s= tatus=3D0 QTime=3D2162 [junit4] 2> 2727129 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.c.ZkController tlog_replica_test_recovery_s= hard1_replica_t1 starting background replication from leader [junit4] 2> 2727129 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.c.ReplicateFromLeader Will start replicatio= n from leader with poll interval: 00:00:03 [junit4] 2> 2727130 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.h.ReplicationHandler Poll scheduled at an i= nterval of 3000ms [junit4] 2> 2727130 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.h.ReplicationHandler Commits will be reserv= ed for 10000ms. [junit4] 2> 2727130 INFO (indexFetcher-10310-thread-1) [n:127.0.0.1:5= 0137_solr c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica= _test_recovery_shard1_replica_t1] o.a.s.h.IndexFetcher Replica core_node4 i= s leader but it's state is down, skipping replication [junit4] 2> 2727132 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path= =3D/admin/cores params=3D{qt=3D/admin/cores&coreNodeName=3Dcore_node3&colle= ction.configName=3Dconf&newCollection=3Dtrue&name=3Dtlog_replica_test_recov= ery_shard1_replica_t1&action=3DCREATE&numShards=3D1&collection=3Dtlog_repli= ca_test_recovery&shard=3Dshard1&wt=3Djavabin&version=3D2&replicaType=3DTLOG= } status=3D0 QTime=3D2223 [junit4] 2> 2727135 INFO (qtp1387007808-31124) [n:127.0.0.1:50137_sol= r ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active fo= r at most 30 seconds. Check all shard replicas [junit4] 2> 2727239 INFO (zkCallback-10169-thread-2-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2727239 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2727240 INFO (zkCallback-10171-thread-1-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2727239 INFO (zkCallback-10171-thread-3-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [2]) [junit4] 2> 2728135 INFO (qtp1387007808-31124) [n:127.0.0.1:50137_sol= r ] o.a.s.s.HttpSolrCall [admin] webapp=3Dnull path=3D/admin/collections= params=3D{pullReplicas=3D0&replicationFactor=3D0&collection.configName=3Dc= onf&maxShardsPerNode=3D100&name=3Dtlog_replica_test_recovery&nrtReplicas=3D= 0&action=3DCREATE&numShards=3D1&tlogReplicas=3D2&wt=3Djavabin&version=3D2} = status=3D0 QTime=3D3662 [junit4] 2> 2728144 INFO (qtp1387007808-31127) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.u.p.LogUpdateProcessorFactory [tlog_replica= _test_recovery_shard1_replica_t1] webapp=3D/solr path=3D/update params=3D{= update.distrib=3DFROMLEADER&distrib.from=3Dhttp://127.0.0.1:50138/solr/tlog= _replica_test_recovery_shard1_replica_t2/&wt=3Djavabin&version=3D2}{add=3D[= 3 (1591188488318877696), 4 (1591188488320974848)]} 0 1 [junit4] 2> 2728144 INFO (qtp469824676-31132) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.p.LogUpdateProcessorFactory [tlog_replica_= test_recovery_shard1_replica_t2] webapp=3D/solr path=3D/update params=3D{_= stateVer_=3Dtlog_replica_test_recovery:5&wt=3Djavabin&version=3D2}{add=3D[3= (1591188488318877696), 4 (1591188488320974848)]} 0 4 [junit4] 2> 2728146 INFO (qtp1387007808-31128) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.u.p.LogUpdateProcessorFactory [tlog_replica= _test_recovery_shard1_replica_t1] webapp=3D/solr path=3D/update params=3D{= update.distrib=3DFROMLEADER&waitSearcher=3Dtrue&openSearcher=3Dtrue&commit= =3Dtrue&softCommit=3Dfalse&distrib.from=3Dhttp://127.0.0.1:50138/solr/tlog_= replica_test_recovery_shard1_replica_t2/&commit_end_point=3Dtrue&wt=3Djavab= in&version=3D2&expungeDeletes=3Dfalse}{commit=3D} 0 0 [junit4] 2> 2728147 INFO (qtp469824676-31136) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.DirectUpdateHandler2 start commit{_version= _=3D1591188488326217728,optimize=3Dfalse,openSearcher=3Dtrue,waitSearcher= =3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dfalse,prepareCommit=3Dfalse} [junit4] 2> 2728147 INFO (qtp469824676-31136) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.SolrIndexWriter Calling setCommitData with= IW:org.apache.solr.update.SolrIndexWriter@78f4edc commitCommandVersion:159= 1188488326217728 [junit4] 2> 2728158 INFO (qtp469824676-31136) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.s.SolrIndexSearcher Opening [Searcher@1ab7c2= bb[tlog_replica_test_recovery_shard1_replica_t2] main] [junit4] 2> 2728158 INFO (qtp469824676-31136) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.DirectUpdateHandler2 end_commit_flush [junit4] 2> 2728160 INFO (searcherExecutor-10299-thread-1-processing-= n:127.0.0.1:50138_solr x:tlog_replica_test_recovery_shard1_replica_t2 s:sha= rd1 c:tlog_replica_test_recovery r:core_node4) [n:127.0.0.1:50138_solr c:tl= og_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_recovery= _shard1_replica_t2] o.a.s.c.SolrCore [tlog_replica_test_recovery_shard1_rep= lica_t2] Registered new searcher Searcher@1ab7c2bb[tlog_replica_test_recove= ry_shard1_replica_t2] main{ExitableDirectoryReader(UninvertingDirectoryRead= er(Uninverting(_0(8.0.0):C2)))} [junit4] 2> 2728160 INFO (qtp469824676-31136) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.p.LogUpdateProcessorFactory [tlog_replica_= test_recovery_shard1_replica_t2] webapp=3D/solr path=3D/update params=3D{u= pdate.distrib=3DFROMLEADER&waitSearcher=3Dtrue&openSearcher=3Dtrue&commit= =3Dtrue&softCommit=3Dfalse&distrib.from=3Dhttp://127.0.0.1:50138/solr/tlog_= replica_test_recovery_shard1_replica_t2/&commit_end_point=3Dtrue&wt=3Djavab= in&version=3D2&expungeDeletes=3Dfalse}{commit=3D} 0 13 [junit4] 2> 2728161 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.p.LogUpdateProcessorFactory [tlog_replica_= test_recovery_shard1_replica_t2] webapp=3D/solr path=3D/update params=3D{_= stateVer_=3Dtlog_replica_test_recovery:5&commit=3Dtrue&wt=3Djavabin&version= =3D2}{commit=3D} 0 15 [junit4] 2> 2728165 INFO (qtp1387007808-31127) [n:127.0.0.1:50137_sol= r c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_replica_test_re= covery_shard1_replica_t1] o.a.s.u.p.LogUpdateProcessorFactory [tlog_replica= _test_recovery_shard1_replica_t1] webapp=3D/solr path=3D/update params=3D{= update.distrib=3DFROMLEADER&distrib.from=3Dhttp://127.0.0.1:50138/solr/tlog= _replica_test_recovery_shard1_replica_t2/&wt=3Djavabin&version=3D2}{add=3D[= 5 (1591188488342994944)]} 0 0 [junit4] 2> 2728166 INFO (qtp469824676-31137) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.p.LogUpdateProcessorFactory [tlog_replica_= test_recovery_shard1_replica_t2] webapp=3D/solr path=3D/update params=3D{w= t=3Djavabin&version=3D2}{add=3D[5 (1591188488342994944)]} 0 3 [junit4] 2> 2728167 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.c.ChaosMonkey monkey: kill jetty! 50137 [junit4] 2> 2728168 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@46= 67b60{HTTP/1.1,[http/1.1]}{127.0.0.1:0} [junit4] 2> 2728168 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer in= stance=3D1230440700 [junit4] 2> 2728169 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters f= or registry=3Dsolr.node, tag=3Dnull [junit4] 2> 2728169 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apac= he.solr.metrics.reporters.SolrJmxReporter@1a83874: rootName =3D solr_50137,= domain =3D solr.node, service url =3D null, agent id =3D null] for registr= y solr.node / com.codahale.metrics.MetricRegistry@42ce66e [junit4] 2> 2728181 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters f= or registry=3Dsolr.jvm, tag=3Dnull [junit4] 2> 2728181 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apac= he.solr.metrics.reporters.SolrJmxReporter@16842cc4: rootName =3D solr_50137= , domain =3D solr.jvm, service url =3D null, agent id =3D null] for registr= y solr.jvm / com.codahale.metrics.MetricRegistry@75099da1 [junit4] 2> 2728190 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters f= or registry=3Dsolr.jetty, tag=3Dnull [junit4] 2> 2728190 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apac= he.solr.metrics.reporters.SolrJmxReporter@39d30d60: rootName =3D solr_50137= , domain =3D solr.jetty, service url =3D null, agent id =3D null] for regis= try solr.jetty / com.codahale.metrics.MetricRegistry@7aae97a4 [junit4] 2> 2728192 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.c.ZkController Remove node as live in ZooKeepe= r:/live_nodes/127.0.0.1:50137_solr [junit4] 2> 2728194 INFO (zkCallback-10181-thread-1) [ ] o.a.s.c.c= .ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1) [junit4] 2> 2728194 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters f= or registry=3Dsolr.cluster, tag=3Dnull [junit4] 2> 2728194 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader Upda= ted live nodes from ZooKeeper... (2) -> (1) [junit4] 2> 2728194 INFO (zkCallback-10171-thread-3-processing-n:127.= 0.0.1:50137_solr) [n:127.0.0.1:50137_solr ] o.a.s.c.c.ZkStateReader Upda= ted live nodes from ZooKeeper... (2) -> (1) [junit4] 2> 2728196 INFO (coreCloseExecutor-10311-thread-1) [n:127.0.= 0.1:50137_solr c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_re= plica_test_recovery_shard1_replica_t1] o.a.s.c.SolrCore [tlog_replica_test_= recovery_shard1_replica_t1] CLOSING SolrCore org.apache.solr.core.SolrCore= @3535590e [junit4] 2> 2728196 INFO (coreCloseExecutor-10311-thread-1) [n:127.0.= 0.1:50137_solr c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_re= plica_test_recovery_shard1_replica_t1] o.a.s.m.SolrMetricManager Closing me= tric reporters for registry=3Dsolr.core.tlog_replica_test_recovery.shard1.r= eplica_t1, tag=3D892688654 [junit4] 2> 2728196 INFO (coreCloseExecutor-10311-thread-1) [n:127.0.= 0.1:50137_solr c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_re= plica_test_recovery_shard1_replica_t1] o.a.s.m.r.SolrJmxReporter Closing re= porter [org.apache.solr.metrics.reporters.SolrJmxReporter@3abce669: rootNam= e =3D solr_50137, domain =3D solr.core.tlog_replica_test_recovery.shard1.re= plica_t1, service url =3D null, agent id =3D null] for registry solr.core.t= log_replica_test_recovery.shard1.replica_t1 / com.codahale.metrics.MetricRe= gistry@18f41f8d [junit4] 2> 2728205 INFO (coreCloseExecutor-10311-thread-1) [n:127.0.= 0.1:50137_solr c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_re= plica_test_recovery_shard1_replica_t1] o.a.s.m.SolrMetricManager Closing me= tric reporters for registry=3Dsolr.collection.tlog_replica_test_recovery.sh= ard1.leader, tag=3D892688654 [junit4] 2> 2728207 INFO (coreCloseExecutor-10311-thread-1) [n:127.0.= 0.1:50137_solr c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_re= plica_test_recovery_shard1_replica_t1] o.a.s.u.DirectUpdateHandler2 Committ= ing on IndexWriter close. [junit4] 2> 2728207 INFO (coreCloseExecutor-10311-thread-1) [n:127.0.= 0.1:50137_solr c:tlog_replica_test_recovery s:shard1 r:core_node3 x:tlog_re= plica_test_recovery_shard1_replica_t1] o.a.s.u.SolrIndexWriter Calling setC= ommitData with IW:org.apache.solr.update.SolrIndexWriter@120c74fd commitCom= mandVersion:0 [junit4] 2> 2728210 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.c.Overseer Overseer (id=3D72122435697967110-12= 7.0.0.1:50137_solr-n_0000000000) closing [junit4] 2> 2728210 INFO (OverseerStateUpdate-72122435697967110-127.0= .0.1:50137_solr-n_0000000000) [n:127.0.0.1:50137_solr ] o.a.s.c.Overseer= Overseer Loop exiting : 127.0.0.1:50137_solr [junit4] 2> 2728211 WARN (OverseerAutoScalingTriggerThread-7212243569= 7967110-127.0.0.1:50137_solr-n_0000000000) [n:127.0.0.1:50137_solr ] o.a= .s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are clos= ed, exiting. [junit4] 2> 2728213 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.OverseerElectionCont= ext I am going to be the leader 127.0.0.1:50138_solr [junit4] 2> 2728215 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletCont= extHandler@332bcb7a{/solr,null,UNAVAILABLE} [junit4] 2> 2728215 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.e.j.s.session Stopped scavenging [junit4] 2> 2728216 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.Overseer Overseer (i= d=3D72122435697967109-127.0.0.1:50138_solr-n_0000000001) starting [junit4] 2> 2728216 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.c.ChaosMonkey monkey: stop jetty! 50137 [junit4] 2> 2728223 INFO (qtp469824676-31134) [n:127.0.0.1:50138_solr= c:tlog_replica_test_recovery s:shard1 r:core_node4 x:tlog_replica_test_rec= overy_shard1_replica_t2] o.a.s.u.p.LogUpdateProcessorFactory [tlog_replica_= test_recovery_shard1_replica_t2] webapp=3D/solr path=3D/update params=3D{w= t=3Djavabin&version=3D2}{add=3D[6 (1591188488405909504)]} 0 0 [junit4] 2> 2728223 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.a.s.c.ChaosMonkey monkey: starting jetty! 50137 [junit4] 2> 2728223 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestam= p: 2017-11-21T16:27:37-05:00, git hash: 82b8fb23f757335bb3329d540ce37a2a261= 5f0a8 [junit4] 2> 2728227 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.e.j.s.session DefaultSessionIdManager workerName= =3Dnode0 [junit4] 2> 2728227 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.e.j.s.session No SessionScavenger set, using defau= lts [junit4] 2> 2728227 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.e.j.s.session Scavenging every 660000ms [junit4] 2> 2728230 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletCont= extHandler@715a144d{/solr,null,AVAILABLE} [junit4] 2> 2728232 INFO (zkCallback-10169-thread-1-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [1]) [junit4] 2> 2728232 INFO (zkCallback-10169-thread-2-processing-n:127.= 0.0.1:50138_solr) [n:127.0.0.1:50138_solr ] o.a.s.c.c.ZkStateReader A cl= uster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged = path:/collections/tlog_replica_test_recovery/state.json] for collection [tl= og_replica_test_recovery] has occurred - updating... (live nodes size: [1]) [junit4] 2> 2728232 INFO (TEST-TestTlogReplica.testRecovery-seed#[624= 230E011B6037C]) [ ] o.e.j [...truncated too long message...] 00000000 [junit4] 2> =092=09/solr/collections/collection1/leader_elect/shard1/e= lection/72122470840729611-core_node8-n_0000000003 [junit4] 2> =092=09/solr/overseer_elect/election/72122470840729629-127= .0.0.1:52119_solr-n_0000000008 [junit4] 2> =092=09/solr/collections/collection1/leader_elect/shard1/e= lection/72122470840729605-core_node10-n_0000000004 [junit4] 2> =092=09/solr/collections/collection1/leader_elect/shard1/e= lection/72122470840729614-core_node6-n_0000000002 [junit4] 2>=20 [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2>=20 [junit4] 2> =0922=09/solr/live_nodes [junit4] 2> =0922=09/solr/collections [junit4] 2> =096=09/solr/overseer/queue-work [junit4] 2> =096=09/solr/autoscaling/events/.auto_add_replicas [junit4] 2> =096=09/solr/overseer/queue [junit4] 2> =096=09/solr/overseer/collection-queue-work [junit4] 2> =092=09/solr/autoscaling/events/node_lost_triggerMR [junit4] 2> =092=09/solr/autoscaling/events/node_added_triggerCTOOR [junit4] 2>=20 [junit4] 2> NOTE: leaving temporary files on disk at: /Users/jenkins/w= orkspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.c= loud.autoscaling.TriggerIntegrationTest_624230E011B6037C-001 [junit4] 2> Feb 01, 2018 9:12:09 AM com.carrotsearch.randomizedtesting= .ThreadLeakControl checkThreadLeaks [junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thre= ad(s). [junit4] 2> NOTE: test params are: codec=3DFastCompressingStoredFields= (storedFieldsFormat=3DCompressingStoredFieldsFormat(compressionMode=3DFAST,= chunkSize=3D8, maxDocsPerChunk=3D814, blockSize=3D742), termVectorsFormat= =3DCompressingTermVectorsFormat(compressionMode=3DFAST, chunkSize=3D8, bloc= kSize=3D742)), sim=3DAsserting(org.apache.lucene.search.similarities.Assert= ingSimilarity@3cf09b88), locale=3Dpt-GQ, timezone=3DAsia/Krasnoyarsk [junit4] 2> NOTE: Mac OS X 10.11.6 x86_64/Oracle Corporation 9 (64-bit= )/cpus=3D3,threads=3D1,free=3D274232032,total=3D536870912 [junit4] 2> NOTE: All tests run in this JVM: [AddSchemaFieldsUpdatePro= cessorFactoryTest, TestSizeLimitedDistributedMap, ReplicationFactorTest, De= bugComponentTest, TestMinMaxOnMultiValuedField, SimpleFacetsTest, TestDefau= ltStatsCache, ChaosMonkeySafeLeaderWithPullReplicasTest, ClassificationUpda= teProcessorIntegrationTest, SolrCmdDistributorTest, SolrCoreCheckLockOnStar= tupTest, DisMaxRequestHandlerTest, TestLargeCluster, SaslZkACLProviderTest,= DocValuesMissingTest, SolrMetricReporterTest, SpellCheckComponentTest, Tes= tSegmentSorting, TestComplexPhraseLeadingWildcard, TestPivotHelperCode, Tes= tCloudNestedDocsSort, CloneFieldUpdateProcessorFactoryTest, TestNoOpRegener= ator, BooleanFieldTest, ResponseLogComponentTest, TestSimDistributedQueue, = TestIndexingPerformance, TestRestoreCore, TestSolrCoreParser, CustomHighlig= htComponentTest, BadComponentTest, TestPerFieldSimilarityWithDefaultOverrid= e, SuggesterTest, TestSearcherReuse, EchoParamsTest, TestRequestStatusColle= ctionAPI, BadIndexSchemaTest, ChaosMonkeySafeLeaderTest, ReplaceNodeNoTarge= tTest, BasicAuthStandaloneTest, DistributedFacetPivotWhiteBoxTest, CheckHdf= sIndexTest, TestSolrQueryResponse, ClusterStateUpdateTest, FacetPivotSmallT= est, TestWordDelimiterFilterFactory, IgnoreCommitOptimizeUpdateProcessorFac= toryTest, ZkControllerTest, TestLMJelinekMercerSimilarityFactory, JsonLoade= rTest, TestDocTermOrds, TestQuerySenderListener, TestRawTransformer, Overse= erTaskQueueTest, ScriptEngineTest, TestCloudJSONFacetJoinDomain, TermVector= ComponentTest, FullSolrCloudDistribCmdsTest, MetricUtilsTest, TestManagedSc= hemaThreadSafety, TestCollectionsAPIViaSolrCloudCluster, BaseCdcrDistribute= dZkTest, TestCoreBackup, ReturnFieldsTest, TestLegacyNumericRangeQueryBuild= er, TestSubQueryTransformerDistrib, ZkStateWriterTest, TestSearchPerf, Hdfs= TlogReplayBufferedWhileIndexingTest, TestLeaderElectionWithEmptyReplica, Te= stManagedStopFilterFactory, UpdateParamsTest, TestFieldCacheReopen, DeleteR= eplicaTest, TestRandomFaceting, TestDynamicFieldCollectionResource, Spatial= RPTFieldTypeTest, TestComponentsName, PreAnalyzedUpdateProcessorTest, TestH= ashQParserPlugin, OutOfBoxZkACLAndCredentialsProvidersTest, TestSolrCloudWi= thHadoopAuthPlugin, TestExceedMaxTermLength, TestLRUStatsCache, TestStressV= ersions, DistributedIntervalFacetingTest, TestDownShardTolerantSearch, Test= ComputePlanAction, ConnectionManagerTest, TestMiniSolrCloudClusterSSL, Auto= AddReplicasPlanActionTest, TestJettySolrRunner, AsyncCallRequestStatusRespo= nseTest, TestDistributedMissingSort, TestSolrIndexConfig, TestExactSharedSt= atsCache, TestDFISimilarityFactory, RankQueryTest, LegacyCloudClusterPropTe= st, TestDistributedGrouping, MinimalSchemaTest, SolrJmxReporterCloudTest, T= estDeleteCollectionOnDownNodes, TestCloudDeleteByQuery, SuggesterWFSTTest, = TestSerializedLuceneMatchVersion, SuggestComponentTest, SliceStateTest, Tes= tDocumentBuilder, SchemaApiFailureTest, PrimitiveFieldTypeTest, AtomicUpdat= esTest, AnalysisErrorHandlingTest, QueryParsingTest, JSONWriterTest, Rollin= gRestartTest, PrimUtilsTest, TestDFRSimilarityFactory, TestStressInPlaceUpd= ates, TestLocalFSCloudBackupRestore, PeerSyncTest, TestLeaderInitiatedRecov= eryThread, HdfsAutoAddReplicasIntegrationTest, TestExtendedDismaxParser, CS= VRequestHandlerTest, JavabinLoaderTest, TestRTGBase, TestFileDictionaryLook= up, NumberUtilsTest, TestObjectReleaseTracker, TestFieldCollectionResource,= TestFilteredDocIdSet, JvmMetricsTest, TlogReplayBufferedWhileIndexingTest,= CoreAdminRequestStatusTest, FieldAnalysisRequestHandlerTest, UUIDUpdatePro= cessorFallbackTest, TestSubQueryTransformer, CdcrVersionReplicationTest, Up= dateLogTest, UUIDFieldTest, SystemLogListenerTest, TestLuceneMatchVersion, = TestNumericTerms32, TestPushWriter, TestAuthorizationFramework, QueryResult= KeyTest, HdfsWriteToMultipleCollectionsTest, DataDrivenBlockJoinTest, TestS= chemaNameResource, DeleteLastCustomShardedReplicaTest, TestGraphMLResponseW= riter, TestNumericTokenStream, SolrCoreMetricManagerTest, TestRecoveryHdfs,= CoreAdminHandlerTest, HdfsCollectionsAPIDistributedZkTest, TestPullReplica= ErrorHandling, TestReplicationHandlerBackup, PropertiesRequestHandlerTest, = SimplePostToolTest, ClusterStateTest, TestAnalyzedSuggestions, HdfsNNFailov= erTest, TestDelegationWithHadoopAuth, TestStressReorder, UninvertDocValuesM= ergePolicyTest, TestMacroExpander, ConjunctionSolrSpellCheckerTest, TestFuz= zyAnalyzedSuggestions, MultiThreadedOCPTest, TestWriterPerf, HighlighterCon= figTest, TestSQLHandlerNonCloud, MoveReplicaHDFSTest, TestPHPSerializedResp= onseWriter, TestManagedResourceStorage, PreAnalyzedFieldTest, LoggingHandle= rTest, HttpPartitionTest, TestCrossCoreJoin, TestHashPartitioner, TestCodec= Support, TestExportWriter, TestSolrCoreProperties, TestRuleBasedAuthorizati= onPlugin, VMParamsZkACLAndCredentialsProvidersTest, SolrShardReporterTest, = TestStandardQParsers, RecoveryAfterSoftCommitTest, BasicDistributedZkTest, = TestReplicationHandler, TestDistributedSearch, TestJoin, DistributedTermsCo= mponentTest, TestCoreContainer, TestSolr4Spatial, SolrCoreTest, TestGroupin= gSearch, TestSort, TestFiltering, TestFunctionQuery, BasicFunctionalityTest= , TestLazyCores, ShowFileRequestHandlerTest, DistributedQueryElevationCompo= nentTest, TestCoreDiscovery, AnalysisAfterCoreReloadTest, SignatureUpdatePr= ocessorFactoryTest, SpellCheckCollatorTest, SuggesterFSTTest, DocValuesTest= , SuggesterTSTTest, TestStressLucene, TestTrie, SpatialFilterTest, TestCSVL= oader, NoCacheHeaderTest, TestUpdate, TestAtomicUpdateErrorCases, DirectUpd= ateHandlerOptimizeTest, DefaultValueUpdateProcessorTest, StatelessScriptUpd= ateProcessorFactoryTest, SortByFunctionTest, DocValuesMultiTest, DistanceFu= nctionTest, TestSolrDeletionPolicy1, XsltUpdateRequestHandlerTest, CacheHea= derTest, IndexBasedSpellCheckerTest, TestSurroundQueryParser, TestQueryUtil= s, TestReversedWildcardFilterFactory, DocumentAnalysisRequestHandlerTest, T= estQueryTypes, TestOmitPositions, FileBasedSpellCheckerTest, XmlUpdateReque= stHandlerTest, RequestHandlersTest, DocumentBuilderTest, TestValueSourceCac= he, MoreLikeThisHandlerTest, TestSolrQueryParser, IndexSchemaRuntimeFieldTe= st, RegexBoostProcessorTest, IndexSchemaTest, TestJmxIntegration, TestColla= tionField, UpdateRequestProcessorFactoryTest, UniqFieldsUpdateProcessorFact= oryTest, TestPartialUpdateDeduplication, SearchHandlerTest, TestLFUCache, T= estQuerySenderNoQuery, CopyFieldTest, SolrIndexConfigTest, TestStressRecove= ry, TestMergePolicyConfig, TestSolrDeletionPolicy2, MultiTermTest, TestDocS= et, TestBinaryField, NumericFieldsTest, TestConfig, ExternalFileFieldSortTe= st, DirectSolrConnectionTest, NotRequiredUniqueKeyTest, SpellPossibilityIte= ratorTest, SynonymTokenizerTest, TestLMDirichletSimilarityFactory, TestBM25= SimilarityFactory, TestFastWriter, TimeZoneUtilsTest, ResourceLoaderTest, O= penExchangeRatesOrgProviderTest, URLClassifyProcessorTest, PluginInfoTest, = TestFastLRUCache, DateMathParserTest, ChaosMonkeyNothingIsSafeTest, Cleanup= OldIndexTest, CloudExitableDirectoryReaderTest, CollectionStateFormat2Test,= ConcurrentCreateRoutedAliasTest, CreateCollectionCleanupTest, DeleteShardT= est, DeleteStatusTest, DistribDocExpirationUpdateProcessorTest, DocValuesNo= tIndexedTest, HealthCheckHandlerTest, LIRRollingUpdatesTest, MigrateRouteKe= yTest, MissingSegmentRecoveryTest, NodeMutatorTest, OverseerCollectionConfi= gSetProcessorTest, OverseerModifyCollectionTest, OverseerRolesTest, RemoteQ= ueryErrorTest, ReplaceNodeTest, TestCloudPseudoReturnFields, TestCloudSearc= herWarming, TestConfigSetsAPIExclusivity, TestLeaderElectionZkExpiry, TestL= ockTree, TestOnReconnectListenerSupport, TestPullReplica, TestStressCloudBl= indAtomicUpdates, TestTolerantUpdateProcessorCloud, TestTolerantUpdateProce= ssorRandomCloud, TestUtilizeNode, ZkShardTermsTest, AssignTest, SimpleColle= ctionCreateDeleteTest, TestCollectionAPI, TestHdfsCloudBackupRestore, TestR= eplicaProperties, AutoAddReplicasIntegrationTest, ComputePlanActionTest, Ex= ecutePlanActionTest, TriggerIntegrationTest] [junit4] Completed [625/774 (3!)] on J1 in 207.77s, 14 tests, 2 failures= <<< FAILURES! [...truncated 41399 lines...] ------=_Part_38_1588760094.1517477804148 Content-Type: text/plain; charset=us-ascii --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org For additional commands, e-mail: dev-help@lucene.apache.org ------=_Part_38_1588760094.1517477804148--