Build: https://builds.apache.org/job/Lucene-Solr-Tests-7.3/23/
3 tests failed. FAILED: org.apache.solr.cloud.TestRebalanceLeaders.test Error Message: Timeout occured while waiting response from server at: https://127.0.0.1:45142/sqd/l Stack Trace: org.apache.solr.client.solrj.SolrServerException: Timeout occured while waiting response from server at: https://127.0.0.1:45142/sqd/l at __randomizedtesting.SeedInfo.seed([C3E174C30991EF8A:4BB54B19A76D8272]:0) at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:654) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:255) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:244) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:483) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:413) at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1105) at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:885) at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:818) at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1219) at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1677) at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1704) at org.apache.solr.cloud.TestRebalanceLeaders.test(TestRebalanceLeaders.java:71) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1737) at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934) at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970) at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984) at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:993) at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:968) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48) at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817) at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468) at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:943) at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829) at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879) at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53) at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) at java.lang.Thread.run(Thread.java:748) Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:171) at java.net.SocketInputStream.read(SocketInputStream.java:141) at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) at sun.security.ssl.InputRecord.read(InputRecord.java:503) at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983) at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940) at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137) at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153) at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282) at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138) at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56) at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259) at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163) at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165) at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273) at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125) at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272) at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111) at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56) at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:542) ... 52 more FAILED: org.apache.solr.cloud.api.collections.TestLocalFSCloudBackupRestore.test Error Message: expected:<COMPLETED> but was:<FAILED> Stack Trace: java.lang.AssertionError: expected:<COMPLETED> but was:<FAILED> at __randomizedtesting.SeedInfo.seed([C3E174C30991EF8A:4BB54B19A76D8272]:0) at org.junit.Assert.fail(Assert.java:93) at org.junit.Assert.failNotEquals(Assert.java:647) at org.junit.Assert.assertEquals(Assert.java:128) at org.junit.Assert.assertEquals(Assert.java:147) at org.apache.solr.cloud.api.collections.AbstractCloudBackupRestoreTestCase.testBackupAndRestore(AbstractCloudBackupRestoreTestCase.java:289) at org.apache.solr.cloud.api.collections.AbstractCloudBackupRestoreTestCase.test(AbstractCloudBackupRestoreTestCase.java:142) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1737) at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934) at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970) at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48) at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817) at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468) at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:943) at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829) at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879) at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53) at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) at java.lang.Thread.run(Thread.java:748) FAILED: org.apache.solr.cloud.cdcr.CdcrBootstrapTest.testBootstrapWithSourceCluster Error Message: Error from server at https://127.0.0.1:38298/solr: KeeperErrorCode = NoNode for /overseer/collection-queue-work/qnr-0000000000 Stack Trace: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at https://127.0.0.1:38298/solr: KeeperErrorCode = NoNode for /overseer/collection-queue-work/qnr-0000000000 at __randomizedtesting.SeedInfo.seed([C3E174C30991EF8A:1AB725070AF5FCC0]:0) at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:643) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:255) at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:244) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:483) at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:413) at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1105) at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:885) at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:818) at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:194) at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:211) at org.apache.solr.cloud.cdcr.CdcrBootstrapTest.testBootstrapWithSourceCluster(CdcrBootstrapTest.java:174) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1737) at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934) at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970) at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48) at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817) at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468) at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:943) at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829) at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879) at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57) at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53) at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47) at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64) at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54) at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36) at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368) at java.lang.Thread.run(Thread.java:748) Build Log: [...truncated 12160 lines...] [junit4] Suite: org.apache.solr.cloud.api.collections.TestLocalFSCloudBackupRestore [junit4] 2> Creating dataDir: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/init-core-data-001 [junit4] 2> 146431 WARN (SUITE-TestLocalFSCloudBackupRestore-seed#[C3E174C30991EF8A]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=5 numCloses=5 [junit4] 2> 146431 INFO (SUITE-TestLocalFSCloudBackupRestore-seed#[C3E174C30991EF8A]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true [junit4] 2> 146432 INFO (SUITE-TestLocalFSCloudBackupRestore-seed#[C3E174C30991EF8A]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN) [junit4] 2> 146466 INFO (SUITE-TestLocalFSCloudBackupRestore-seed#[C3E174C30991EF8A]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom [junit4] 2> 146469 INFO (SUITE-TestLocalFSCloudBackupRestore-seed#[C3E174C30991EF8A]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001 [junit4] 2> 146469 INFO (SUITE-TestLocalFSCloudBackupRestore-seed#[C3E174C30991EF8A]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 146471 INFO (Thread-65) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0 [junit4] 2> 146471 INFO (Thread-65) [ ] o.a.s.c.ZkTestServer Starting server [junit4] 2> 146474 ERROR (Thread-65) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes [junit4] 2> 146576 INFO (SUITE-TestLocalFSCloudBackupRestore-seed#[C3E174C30991EF8A]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:41261 [junit4] 2> 146706 INFO (zkConnectionManagerCallback-100-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 147185 INFO (jetty-launcher-97-thread-1) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T23:27:37+02:00, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8 [junit4] 2> 147187 INFO (jetty-launcher-97-thread-1) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0 [junit4] 2> 147188 INFO (jetty-launcher-97-thread-1) [ ] o.e.j.s.session No SessionScavenger set, using defaults [junit4] 2> 147188 INFO (jetty-launcher-97-thread-1) [ ] o.e.j.s.session Scavenging every 660000ms [junit4] 2> 147188 INFO (jetty-launcher-97-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@432c6ef0{/solr,null,AVAILABLE} [junit4] 2> 147219 INFO (jetty-launcher-97-thread-2) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T23:27:37+02:00, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8 [junit4] 2> 147462 INFO (jetty-launcher-97-thread-2) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0 [junit4] 2> 147462 INFO (jetty-launcher-97-thread-2) [ ] o.e.j.s.session No SessionScavenger set, using defaults [junit4] 2> 147462 INFO (jetty-launcher-97-thread-2) [ ] o.e.j.s.session Scavenging every 660000ms [junit4] 2> 147462 INFO (jetty-launcher-97-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@4ba38461{/solr,null,AVAILABLE} [junit4] 2> 147551 INFO (jetty-launcher-97-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@242e25f2{SSL,[ssl, http/1.1]}{127.0.0.1:38790} [junit4] 2> 147587 INFO (jetty-launcher-97-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@64cb1b64{SSL,[ssl, http/1.1]}{127.0.0.1:34636} [junit4] 2> 147587 INFO (jetty-launcher-97-thread-1) [ ] o.e.j.s.Server Started @159670ms [junit4] 2> 147587 INFO (jetty-launcher-97-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34636} [junit4] 2> 147600 INFO (jetty-launcher-97-thread-2) [ ] o.e.j.s.Server Started @159682ms [junit4] 2> 147600 INFO (jetty-launcher-97-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=38790} [junit4] 2> 147601 ERROR (jetty-launcher-97-thread-2) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 147616 INFO (jetty-launcher-97-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.3.0 [junit4] 2> 147616 INFO (jetty-launcher-97-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 147617 INFO (jetty-launcher-97-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 147617 INFO (jetty-launcher-97-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-03-21T10:19:52.249Z [junit4] 2> 147616 ERROR (jetty-launcher-97-thread-1) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 147619 INFO (jetty-launcher-97-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.3.0 [junit4] 2> 147619 INFO (jetty-launcher-97-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 147619 INFO (jetty-launcher-97-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null [junit4] 2> 147619 INFO (jetty-launcher-97-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-03-21T10:19:52.251Z [junit4] 2> 147710 INFO (zkConnectionManagerCallback-104-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 147746 INFO (zkConnectionManagerCallback-102-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 147747 INFO (jetty-launcher-97-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 147847 INFO (jetty-launcher-97-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 147982 INFO (jetty-launcher-97-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:41261/solr [junit4] 2> 148124 INFO (zkConnectionManagerCallback-108-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 148295 INFO (jetty-launcher-97-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:41261/solr [junit4] 2> 148367 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn Unable to read additional data from client sessionid 0x100ec54fa290003, likely client has closed socket [junit4] 2> 148368 INFO (zkConnectionManagerCallback-112-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 148497 INFO (zkConnectionManagerCallback-114-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 148566 INFO (zkConnectionManagerCallback-116-thread-1-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 149742 INFO (jetty-launcher-97-thread-1) [n:127.0.0.1:34636_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 149743 INFO (jetty-launcher-97-thread-1) [n:127.0.0.1:34636_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:34636_solr [junit4] 2> 149792 INFO (jetty-launcher-97-thread-1) [n:127.0.0.1:34636_solr ] o.a.s.c.Overseer Overseer (id=72317443756326917-127.0.0.1:34636_solr-n_0000000000) starting [junit4] 2> 149925 INFO (jetty-launcher-97-thread-2) [n:127.0.0.1:38790_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 149939 INFO (zkConnectionManagerCallback-122-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 149941 INFO (jetty-launcher-97-thread-2) [n:127.0.0.1:38790_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38790_solr [junit4] 2> 149941 INFO (jetty-launcher-97-thread-1) [n:127.0.0.1:34636_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:41261/solr ready [junit4] 2> 150112 INFO (zkCallback-113-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 150293 INFO (zkCallback-121-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 150293 INFO (zkCallback-115-thread-1-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 150439 INFO (jetty-launcher-97-thread-1) [n:127.0.0.1:34636_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34636_solr [junit4] 2> 150528 INFO (zkCallback-121-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 150548 INFO (zkCallback-113-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 150564 INFO (zkCallback-115-thread-1-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 151133 INFO (jetty-launcher-97-thread-2) [n:127.0.0.1:38790_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_38790.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 151226 INFO (jetty-launcher-97-thread-2) [n:127.0.0.1:38790_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_38790.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 151279 INFO (jetty-launcher-97-thread-2) [n:127.0.0.1:38790_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_38790.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 151280 INFO (jetty-launcher-97-thread-2) [n:127.0.0.1:38790_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node2/. [junit4] 2> 151662 INFO (jetty-launcher-97-thread-1) [n:127.0.0.1:34636_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34636.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 151860 INFO (jetty-launcher-97-thread-1) [n:127.0.0.1:34636_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34636.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 151861 INFO (jetty-launcher-97-thread-1) [n:127.0.0.1:34636_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34636.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 151862 INFO (jetty-launcher-97-thread-1) [n:127.0.0.1:34636_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node1/. [junit4] 2> 151896 INFO (zkConnectionManagerCallback-126-thread-1-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 151986 INFO (jetty-launcher-97-thread-2) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2) [junit4] 2> 151988 INFO (jetty-launcher-97-thread-2) [n:127.0.0.1:38790_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:41261/solr ready [junit4] 2> 152445 INFO (zkConnectionManagerCallback-128-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 152627 INFO (zkConnectionManagerCallback-132-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected [junit4] 2> 152701 INFO (SUITE-TestLocalFSCloudBackupRestore-seed#[C3E174C30991EF8A]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2) [junit4] 2> 152774 INFO (SUITE-TestLocalFSCloudBackupRestore-seed#[C3E174C30991EF8A]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:41261/solr ready [junit4] 2> 153487 INFO (TEST-TestLocalFSCloudBackupRestore.test-seed#[C3E174C30991EF8A]) [ ] o.a.s.SolrTestCaseJ4 ###Starting test [junit4] 2> 155116 INFO (qtp1298077526-411) [n:127.0.0.1:34636_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf1&version=2&pullReplicas=1&property.customKey=customValue&maxShardsPerNode=6&router.field=shard_s&autoAddReplicas=true&name=backuprestore&nrtReplicas=1&action=CREATE&numShards=2&tlogReplicas=1&wt=javabin and sendToOCPQueue=true [junit4] 2> 155228 INFO (OverseerThreadFactory-303-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.a.c.CreateCollectionCmd Create collection backuprestore [junit4] 2> 155240 WARN (OverseerThreadFactory-303-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.a.c.CreateCollectionCmd Specified number of replicas of 3 on collection backuprestore is higher than the number of Solr instances currently live or live and part of your createNodeSet(2). It's unusual to run two replica of the same slice on the same Solr-instance. [junit4] 2> 155533 INFO (OverseerStateUpdate-72317443756326917-127.0.0.1:34636_solr-n_0000000000) [n:127.0.0.1:34636_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"backuprestore", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"backuprestore_shard1_replica_n1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:34636/solr";, [junit4] 2> "type":"NRT", [junit4] 2> "waitForFinalState":"false"} [junit4] 2> 155535 INFO (OverseerStateUpdate-72317443756326917-127.0.0.1:34636_solr-n_0000000000) [n:127.0.0.1:34636_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"backuprestore", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"backuprestore_shard1_replica_t2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:38790/solr";, [junit4] 2> "type":"TLOG", [junit4] 2> "waitForFinalState":"false"} [junit4] 2> 155548 INFO (OverseerStateUpdate-72317443756326917-127.0.0.1:34636_solr-n_0000000000) [n:127.0.0.1:34636_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"backuprestore", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"backuprestore_shard1_replica_p3", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:34636/solr";, [junit4] 2> "type":"PULL", [junit4] 2> "waitForFinalState":"false"} [junit4] 2> 155549 INFO (OverseerStateUpdate-72317443756326917-127.0.0.1:34636_solr-n_0000000000) [n:127.0.0.1:34636_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"backuprestore", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"backuprestore_shard2_replica_n4", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:38790/solr";, [junit4] 2> "type":"NRT", [junit4] 2> "waitForFinalState":"false"} [junit4] 2> 155550 INFO (OverseerStateUpdate-72317443756326917-127.0.0.1:34636_solr-n_0000000000) [n:127.0.0.1:34636_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"backuprestore", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"backuprestore_shard2_replica_t5", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:34636/solr";, [junit4] 2> "type":"TLOG", [junit4] 2> "waitForFinalState":"false"} [junit4] 2> 155568 INFO (OverseerStateUpdate-72317443756326917-127.0.0.1:34636_solr-n_0000000000) [n:127.0.0.1:34636_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"backuprestore", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"backuprestore_shard2_replica_p6", [junit4] 2> "state":"down", [junit4] 2> "base_url":"https://127.0.0.1:38790/solr";, [junit4] 2> "type":"PULL", [junit4] 2> "waitForFinalState":"false"} [junit4] 2> 156230 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=NRT&property.customKey=customValue&coreNodeName=core_node7&name=backuprestore_shard1_replica_n1&action=CREATE&numShards=2&shard=shard1&wt=javabin [junit4] 2> 156230 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 156339 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=PULL&property.customKey=customValue&coreNodeName=core_node9&name=backuprestore_shard1_replica_p3&action=CREATE&numShards=2&shard=shard1&wt=javabin [junit4] 2> 156392 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=TLOG&property.customKey=customValue&coreNodeName=core_node11&name=backuprestore_shard2_replica_t5&action=CREATE&numShards=2&shard=shard2&wt=javabin [junit4] 2> 156679 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=NRT&property.customKey=customValue&coreNodeName=core_node10&name=backuprestore_shard2_replica_n4&action=CREATE&numShards=2&shard=shard2&wt=javabin [junit4] 2> 156679 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 156842 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=PULL&property.customKey=customValue&coreNodeName=core_node12&name=backuprestore_shard2_replica_p6&action=CREATE&numShards=2&shard=shard2&wt=javabin [junit4] 2> 156876 INFO (zkCallback-115-thread-1-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 156876 INFO (zkCallback-113-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 156892 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=TLOG&property.customKey=customValue&coreNodeName=core_node8&name=backuprestore_shard1_replica_t2&action=CREATE&numShards=2&shard=shard1&wt=javabin [junit4] 2> 156912 INFO (zkCallback-113-thread-2-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 156912 INFO (zkCallback-115-thread-2-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 157075 INFO (zkCallback-113-thread-2-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 157075 INFO (zkCallback-115-thread-2-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 157075 INFO (zkCallback-113-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 157075 INFO (zkCallback-115-thread-1-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 157315 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0 [junit4] 2> 157381 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.s.IndexSchema [backuprestore_shard1_replica_n1] Schema name=minimal [junit4] 2> 157474 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0 [junit4] 2> 157511 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 157511 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.CoreContainer Creating SolrCore 'backuprestore_shard1_replica_n1' using configuration from collection backuprestore, trusted=true [junit4] 2> 157511 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34636.solr.core.backuprestore.shard1.replica_n1' (registry 'solr.core.backuprestore.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 157511 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 157512 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.SolrCore [[backuprestore_shard1_replica_n1] ] Opening new SolrCore at [/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node1/backuprestore_shard1_replica_n1], dataDir=[/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node1/./backuprestore_shard1_replica_n1/data/] [junit4] 2> 157550 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.s.IndexSchema [backuprestore_shard1_replica_p3] Schema name=minimal [junit4] 2> 157569 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 157569 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.c.CoreContainer Creating SolrCore 'backuprestore_shard1_replica_p3' using configuration from collection backuprestore, trusted=true [junit4] 2> 157570 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34636.solr.core.backuprestore.shard1.replica_p3' (registry 'solr.core.backuprestore.shard1.replica_p3') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 157570 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 157570 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.c.SolrCore [[backuprestore_shard1_replica_p3] ] Opening new SolrCore at [/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node1/backuprestore_shard1_replica_p3], dataDir=[/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node1/./backuprestore_shard1_replica_p3/data/] [junit4] 2> 157806 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0 [junit4] 2> 157900 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.s.IndexSchema [backuprestore_shard2_replica_t5] Schema name=minimal [junit4] 2> 157952 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 157952 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.CoreContainer Creating SolrCore 'backuprestore_shard2_replica_t5' using configuration from collection backuprestore, trusted=true [junit4] 2> 157953 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34636.solr.core.backuprestore.shard2.replica_t5' (registry 'solr.core.backuprestore.shard2.replica_t5') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 157953 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 157953 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.SolrCore [[backuprestore_shard2_replica_t5] ] Opening new SolrCore at [/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node1/backuprestore_shard2_replica_t5], dataDir=[/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node1/./backuprestore_shard2_replica_t5/data/] [junit4] 2> 158316 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0 [junit4] 2> 158381 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0 [junit4] 2> 158426 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.s.IndexSchema [backuprestore_shard1_replica_t2] Schema name=minimal [junit4] 2> 158440 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.3.0 [junit4] 2> 158443 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 158443 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.c.CoreContainer Creating SolrCore 'backuprestore_shard1_replica_t2' using configuration from collection backuprestore, trusted=true [junit4] 2> 158443 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_38790.solr.core.backuprestore.shard1.replica_t2' (registry 'solr.core.backuprestore.shard1.replica_t2') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 158444 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 158444 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.c.SolrCore [[backuprestore_shard1_replica_t2] ] Opening new SolrCore at [/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node2/backuprestore_shard1_replica_t2], dataDir=[/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node2/./backuprestore_shard1_replica_t2/data/] [junit4] 2> 158542 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.s.IndexSchema [backuprestore_shard2_replica_n4] Schema name=minimal [junit4] 2> 158544 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 158544 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.c.CoreContainer Creating SolrCore 'backuprestore_shard2_replica_n4' using configuration from collection backuprestore, trusted=true [junit4] 2> 158545 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_38790.solr.core.backuprestore.shard2.replica_n4' (registry 'solr.core.backuprestore.shard2.replica_n4') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 158545 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 158545 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.c.SolrCore [[backuprestore_shard2_replica_n4] ] Opening new SolrCore at [/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node2/backuprestore_shard2_replica_n4], dataDir=[/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node2/./backuprestore_shard2_replica_n4/data/] [junit4] 2> 158570 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 158570 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 158572 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 158572 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 158573 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@18fd539d[backuprestore_shard1_replica_n1] main] [junit4] 2> 158587 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 158588 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 158588 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 158604 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.s.IndexSchema [backuprestore_shard2_replica_p6] Schema name=minimal [junit4] 2> 158605 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 158605 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1595542185691840512 [junit4] 2> 158605 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 158606 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.s.SolrIndexSearcher Opening [Searcher@74b10dcc[backuprestore_shard1_replica_p3] main] [junit4] 2> 158678 INFO (searcherExecutor-308-thread-1-processing-n:127.0.0.1:34636_solr x:backuprestore_shard1_replica_n1 s:shard1 c:backuprestore r:core_node7) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.SolrCore [backuprestore_shard1_replica_n1] Registered new searcher Searcher@18fd539d[backuprestore_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 158730 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 158730 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.c.CoreContainer Creating SolrCore 'backuprestore_shard2_replica_p6' using configuration from collection backuprestore, trusted=true [junit4] 2> 158735 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.ZkShardTerms Successful update of terms at /collections/backuprestore/terms/shard1 to Terms{values={core_node7=0}, version=0} [junit4] 2> 158749 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 158749 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 158750 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 158826 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_38790.solr.core.backuprestore.shard2.replica_p6' (registry 'solr.core.backuprestore.shard2.replica_p6') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@155fcf0d [junit4] 2> 158844 INFO (searcherExecutor-309-thread-1-processing-n:127.0.0.1:34636_solr x:backuprestore_shard1_replica_p3 s:shard1 c:backuprestore r:core_node9) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.c.SolrCore [backuprestore_shard1_replica_p3] Registered new searcher Searcher@74b10dcc[backuprestore_shard1_replica_p3] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 158968 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.c.ZkController backuprestore_shard1_replica_p3 starting background replication from leader [junit4] 2> 158970 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.c.ReplicateFromLeader Will start replication from leader with poll interval: 00:00:03 [junit4] 2> 158989 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 3000ms [junit4] 2> 158989 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 159038 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 159038 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.c.SolrCore [[backuprestore_shard2_replica_p6] ] Opening new SolrCore at [/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node2/backuprestore_shard2_replica_p6], dataDir=[/home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J2/temp/solr.cloud.api.collections.TestLocalFSCloudBackupRestore_C3E174C30991EF8A-001/tempDir-001/node2/./backuprestore_shard2_replica_p6/data/] [junit4] 2> 159125 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard1: total=2 found=1 timeoutin=9960ms [junit4] 2> 159257 INFO (zkCallback-113-thread-3-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 159260 INFO (zkCallback-113-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 159261 INFO (zkCallback-115-thread-1-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 159261 INFO (zkCallback-115-thread-2-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 159740 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 159740 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 159741 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 159741 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 159743 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.s.SolrIndexSearcher Opening [Searcher@977b5a0[backuprestore_shard2_replica_t5] main] [junit4] 2> 159754 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 159755 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 159755 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 159756 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1595542186898751488 [junit4] 2> 159886 INFO (searcherExecutor-310-thread-1-processing-n:127.0.0.1:34636_solr x:backuprestore_shard2_replica_t5 s:shard2 c:backuprestore r:core_node11) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.SolrCore [backuprestore_shard2_replica_t5] Registered new searcher Searcher@977b5a0[backuprestore_shard2_replica_t5] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 159924 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.ZkShardTerms Successful update of terms at /collections/backuprestore/terms/shard2 to Terms{values={core_node11=0}, version=0} [junit4] 2> 160056 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard2: total=2 found=1 timeoutin=9999ms [junit4] 2> 160065 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 160065 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 160069 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 160069 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 160071 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.s.SolrIndexSearcher Opening [Searcher@71cc213b[backuprestore_shard2_replica_n4] main] [junit4] 2> 160090 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 160090 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 160091 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 160091 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1595542187250024448 [junit4] 2> 160138 INFO (searcherExecutor-314-thread-1-processing-n:127.0.0.1:38790_solr x:backuprestore_shard2_replica_n4 s:shard2 c:backuprestore r:core_node10) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.c.SolrCore [backuprestore_shard2_replica_n4] Registered new searcher Searcher@71cc213b[backuprestore_shard2_replica_n4] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 160176 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.c.ZkShardTerms Successful update of terms at /collections/backuprestore/terms/shard2 to Terms{values={core_node10=0, core_node11=0}, version=1} [junit4] 2> 160187 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 160187 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 160188 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 160188 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 160190 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.s.SolrIndexSearcher Opening [Searcher@75d607a4[backuprestore_shard1_replica_t2] main] [junit4] 2> 160208 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 160209 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 160209 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 160223 INFO (searcherExecutor-313-thread-1-processing-n:127.0.0.1:38790_solr x:backuprestore_shard1_replica_t2 s:shard1 c:backuprestore r:core_node8) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.c.SolrCore [backuprestore_shard1_replica_t2] Registered new searcher Searcher@75d607a4[backuprestore_shard1_replica_t2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 160223 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1595542187388436480 [junit4] 2> 160353 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 160353 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 160356 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.c.ZkShardTerms Successful update of terms at /collections/backuprestore/terms/shard1 to Terms{values={core_node7=0, core_node8=0}, version=1} [junit4] 2> 160479 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.s.SolrIndexSearcher Opening [Searcher@20f681e9[backuprestore_shard2_replica_p6] main] [junit4] 2> 160481 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1 [junit4] 2> 160482 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1 [junit4] 2> 160482 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 160499 INFO (zkCallback-113-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 160500 INFO (zkCallback-115-thread-2-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 160500 INFO (zkCallback-113-thread-2-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 160516 INFO (zkCallback-115-thread-3-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 160516 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.c.ZkController backuprestore_shard2_replica_p6 starting background replication from leader [junit4] 2> 160516 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.c.ReplicateFromLeader Will start replication from leader with poll interval: 00:00:03 [junit4] 2> 160552 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 3000ms [junit4] 2> 160552 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 160662 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 160662 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 160662 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:34636/solr/backuprestore_shard2_replica_t5/ [junit4] 2> 160663 INFO (searcherExecutor-320-thread-1-processing-n:127.0.0.1:38790_solr x:backuprestore_shard2_replica_p6 s:shard2 c:backuprestore r:core_node12) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.c.SolrCore [backuprestore_shard2_replica_p6] Registered new searcher Searcher@20f681e9[backuprestore_shard2_replica_p6] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 160663 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.u.PeerSync PeerSync: core=backuprestore_shard2_replica_t5 url=https://127.0.0.1:34636/solr START replicas=[https://127.0.0.1:38790/solr/backuprestore_shard2_replica_n4/] nUpdates=100 [junit4] 2> 160682 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 160682 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 160682 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:34636/solr/backuprestore_shard1_replica_n1/ [junit4] 2> 160683 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.u.PeerSync PeerSync: core=backuprestore_shard1_replica_n1 url=https://127.0.0.1:34636/solr START replicas=[https://127.0.0.1:38790/solr/backuprestore_shard1_replica_t2/] nUpdates=100 [junit4] 2> 161101 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.u.PeerSync PeerSync: core=backuprestore_shard1_replica_n1 url=https://127.0.0.1:34636/solr DONE. We have no versions. sync failed. [junit4] 2> 161101 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.u.PeerSync PeerSync: core=backuprestore_shard2_replica_t5 url=https://127.0.0.1:34636/solr DONE. We have no versions. sync failed. [junit4] 2> 161292 INFO (qtp2009578252-420) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.c.S.Request [backuprestore_shard2_replica_n4] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=29 [junit4] 2> 161294 INFO (qtp2009578252-488) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.c.S.Request [backuprestore_shard1_replica_t2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=1 [junit4] 2> 161294 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate [junit4] 2> 161294 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway [junit4] 2> 161327 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 161295 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate [junit4] 2> 161331 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway [junit4] 2> 161331 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 161335 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.ZkController backuprestore_shard2_replica_t5 stopping background replication from leader [junit4] 2> 161407 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:34636/solr/backuprestore_shard2_replica_t5/ shard2 [junit4] 2> 161437 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:34636/solr/backuprestore_shard1_replica_n1/ shard1 [junit4] 2> 161656 INFO (zkCallback-113-thread-2-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 161656 INFO (zkCallback-113-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 161672 INFO (zkCallback-115-thread-3-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 161672 INFO (zkCallback-115-thread-1-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 161680 INFO (indexFetcher-322-thread-1) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.h.IndexFetcher Replica core_node7 is leader but it's state is down, skipping replication [junit4] 2> 161706 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 161708 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 161709 INFO (qtp2009578252-419) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=PULL&property.customKey=customValue&coreNodeName=core_node12&name=backuprestore_shard2_replica_p6&action=CREATE&numShards=2&shard=shard2&wt=javabin} status=0 QTime=4867 [junit4] 2> 161711 INFO (qtp1298077526-413) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=NRT&property.customKey=customValue&coreNodeName=core_node7&name=backuprestore_shard1_replica_n1&action=CREATE&numShards=2&shard=shard1&wt=javabin} status=0 QTime=5481 [junit4] 2> 161733 INFO (indexFetcher-339-thread-1) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node12 x:backuprestore_shard2_replica_p6] o.a.s.h.IndexFetcher Replica core_node11 is leader but it's state is down, skipping replication [junit4] 2> 161854 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.c.ZkController backuprestore_shard1_replica_t2 starting background replication from leader [junit4] 2> 161854 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.c.ReplicateFromLeader Will start replication from leader with poll interval: 00:00:03 [junit4] 2> 161857 INFO (qtp1298077526-410) [n:127.0.0.1:34636_solr c:backuprestore s:shard2 r:core_node11 x:backuprestore_shard2_replica_t5] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=TLOG&property.customKey=customValue&coreNodeName=core_node11&name=backuprestore_shard2_replica_t5&action=CREATE&numShards=2&shard=shard2&wt=javabin} status=0 QTime=5465 [junit4] 2> 161891 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 3000ms [junit4] 2> 161891 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 161893 INFO (qtp2009578252-422) [n:127.0.0.1:38790_solr c:backuprestore s:shard1 r:core_node8 x:backuprestore_shard1_replica_t2] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=TLOG&property.customKey=customValue&coreNodeName=core_node8&name=backuprestore_shard1_replica_t2&action=CREATE&numShards=2&shard=shard1&wt=javabin} status=0 QTime=5001 [junit4] 2> 162014 INFO (zkCallback-115-thread-1-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 162014 INFO (zkCallback-115-thread-3-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 162015 INFO (zkCallback-113-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 162015 INFO (zkCallback-113-thread-2-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 162261 INFO (qtp1298077526-406) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=PULL&property.customKey=customValue&coreNodeName=core_node9&name=backuprestore_shard1_replica_p3&action=CREATE&numShards=2&shard=shard1&wt=javabin} status=0 QTime=5956 [junit4] 2> 162281 INFO (qtp2009578252-418) [n:127.0.0.1:38790_solr c:backuprestore s:shard2 r:core_node10 x:backuprestore_shard2_replica_n4] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&collection=backuprestore&version=2&replicaType=NRT&property.customKey=customValue&coreNodeName=core_node10&name=backuprestore_shard2_replica_n4&action=CREATE&numShards=2&shard=shard2&wt=javabin} status=0 QTime=5602 [junit4] 2> 162360 INFO (qtp1298077526-411) [n:127.0.0.1:34636_solr ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas [junit4] 2> 162431 INFO (zkCallback-115-thread-1-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 162431 INFO (zkCallback-113-thread-1-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 162431 INFO (zkCallback-115-thread-3-processing-n:127.0.0.1:38790_solr) [n:127.0.0.1:38790_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 162431 INFO (zkCallback-113-thread-2-processing-n:127.0.0.1:34636_solr) [n:127.0.0.1:34636_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/backuprestore/state.json] for collection [backuprestore] has occurred - updating... (live nodes size: [2]) [junit4] 2> 163137 INFO (indexFetcher-322-thread-1) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.h.IndexFetcher Last replication failed, so I'll force replication [junit4] 2> 163137 INFO (indexFetcher-322-thread-1) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node9 x:backuprestore_shard1_replica_p3] o.a.s.h.IndexFetcher Updated masterUrl to https://127.0.0.1:34636/solr/backuprestore_shard1_replica_n1/ [junit4] 2> 163227 INFO (qtp1298077526-409) [n:127.0.0.1:34636_solr c:backuprestore s:shard1 r:core_node7 x:backuprestore_shard1_replica_n1] o.a.s.c.S.Request [backuprestore_shard1_replica_n1] webapp=/solr path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=33 [junit4] 2> 163228 INFO (indexFetcher-322-thread-1) [...truncated too long message...] dId(ZkController.java:1602) [junit4] 2> at org.apache.solr.cloud.ZkController.doGetShardIdAndNodeNameProcess(ZkController.java:1559) [junit4] 2> at org.apache.solr.cloud.ZkController.preRegister(ZkController.java:1668) [junit4] 2> at org.apache.solr.core.CoreContainer.createFromDescriptor(CoreContainer.java:1033) [junit4] 2> ... 43 more [junit4] 2> Caused by: org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/control_collection/state.json [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:130) [junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:54) [junit4] 2> at org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1215) [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.lambda$getData$5(SolrZkClient.java:340) [junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:60) [junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getData(SolrZkClient.java:340) [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.fetchCollectionState(ZkStateReader.java:1247) [junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.getCollectionLive(ZkStateReader.java:1233) [junit4] 2> ... 50 more [junit4] 2> [junit4] 2> 1112568 INFO (qtp250101911-1112) [n:127.0.0.1:45142_sqd%2Fl c:testcollection s:shard5 x:testcollection_shard5_replica_n23] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&name=testcollection_shard5_replica_n23&action=CREATE&numShards=5&collection=testcollection&shard=shard5&wt=javabin&version=2&replicaType=NRT} status=400 QTime=610681 [junit4] 2> 1112569 ERROR (TEST-TestRebalanceLeaders.test-seed#[C3E174C30991EF8A]) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes [junit4] 2> 1112598 INFO (TEST-TestRebalanceLeaders.test-seed#[C3E174C30991EF8A]) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:33364 33364 [junit4] 2> 1112676 INFO (Thread-141) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:33364 33364 [junit4] 2> 1112677 WARN (Thread-141) [ ] o.a.s.c.ZkTestServer Watch limit violations: [junit4] 2> Maximum concurrent create/delete watches above limit: [junit4] 2> [junit4] 2> 37 /solr/aliases.json [junit4] 2> 9 /solr/collections/testcollection/terms/shard1 [junit4] 2> 9 /solr/collections/testcollection/terms/shard3 [junit4] 2> 8 /solr/collections/testcollection/terms/shard2 [junit4] 2> 5 /solr/security.json [junit4] 2> 5 /solr/configs/conf1 [junit4] 2> 2 /solr/collections/collection1/terms/shard1 [junit4] 2> 2 /solr/collections/testcollection/terms/shard4 [junit4] 2> 2 /solr/collections/collection1/terms/shard2 [junit4] 2> 2 /solr/collections/collection1/terms/shard3 [junit4] 2> 2 /solr/collections/collection1/terms/shard4 [junit4] 2> 2 /solr/collections/control_collection/terms/shard1 [junit4] 2> [junit4] 2> Maximum concurrent data watches above limit: [junit4] 2> [junit4] 2> 37 /solr/clusterprops.json [junit4] 2> 37 /solr/clusterstate.json [junit4] 2> 5 /solr/autoscaling.json [junit4] 2> 5 /solr/collections/testcollection/state.json [junit4] 2> 4 /solr/collections/collection1/state.json [junit4] 2> [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2> [junit4] 2> 37 /solr/live_nodes [junit4] 2> 37 /solr/collections [junit4] 2> 5 /solr/overseer/queue [junit4] 2> 5 /solr/overseer/queue-work [junit4] 2> 4 /solr/autoscaling/events/.auto_add_replicas [junit4] 2> 4 /solr/overseer/collection-queue-work [junit4] 2> [junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestRebalanceLeaders -Dtests.method=test -Dtests.seed=C3E174C30991EF8A -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=ja -Dtests.timezone=Mexico/General -Dtests.asserts=true -Dtests.file.encoding=US-ASCII [junit4] ERROR 721s J0 | TestRebalanceLeaders.test <<< [junit4] > Throwable #1: org.apache.solr.client.solrj.SolrServerException: Timeout occured while waiting response from server at: https://127.0.0.1:45142/sqd/l [junit4] > at __randomizedtesting.SeedInfo.seed([C3E174C30991EF8A:4BB54B19A76D8272]:0) [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:654) [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:255) [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:244) [junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:483) [junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:413) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1105) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:885) [junit4] > at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:818) [junit4] > at org.apache.solr.client.solrj.SolrClient.request(SolrClient.java:1219) [junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1677) [junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.createCollection(AbstractFullDistribZkTestBase.java:1704) [junit4] > at org.apache.solr.cloud.TestRebalanceLeaders.test(TestRebalanceLeaders.java:71) [junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsFixedStatement.callStatement(BaseDistributedSearchTestCase.java:993) [junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:968) [junit4] > at java.lang.Thread.run(Thread.java:748) [junit4] > Caused by: java.net.SocketTimeoutException: Read timed out [junit4] > at java.net.SocketInputStream.socketRead0(Native Method) [junit4] > at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) [junit4] > at java.net.SocketInputStream.read(SocketInputStream.java:171) [junit4] > at java.net.SocketInputStream.read(SocketInputStream.java:141) [junit4] > at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) [junit4] > at sun.security.ssl.InputRecord.read(InputRecord.java:503) [junit4] > at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983) [junit4] > at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940) [junit4] > at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) [junit4] > at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137) [junit4] > at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153) [junit4] > at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:282) [junit4] > at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138) [junit4] > at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56) [junit4] > at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259) [junit4] > at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163) [junit4] > at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:165) [junit4] > at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273) [junit4] > at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125) [junit4] > at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272) [junit4] > at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) [junit4] > at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) [junit4] > at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111) [junit4] > at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) [junit4] > at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) [junit4] > at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56) [junit4] > at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:542) [junit4] > ... 52 more [junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-7.3/solr/build/solr-core/test/J0/temp/solr.cloud.TestRebalanceLeaders_C3E174C30991EF8A-001 [junit4] 2> Mar 21, 2018 10:35:57 AM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks [junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s). [junit4] 2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarity(queryNorm=false): {}, locale=ja, timezone=Mexico/General [junit4] 2> NOTE: Linux 4.4.0-112-generic amd64/Oracle Corporation 1.8.0_152 (64-bit)/cpus=4,threads=1,free=192111320,total=434634752 [junit4] 2> NOTE: All tests run in this JVM: [TestSubQueryTransformerDistrib, SolrPluginUtilsTest, DistributedQueryComponentOptimizationTest, CdcrBootstrapTest, TestRebalanceLeaders] [junit4] Completed [78/783 (3!)] on J0 in 722.40s, 1 test, 1 error <<< FAILURES! [...truncated 52052 lines...]
--------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
