Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-MacOSX/227/ Java: 64bit/jdk1.8.0 -XX:+UseCompressedOops -XX:+UseG1GC
1 tests failed. FAILED: org.apache.solr.cloud.TestTlogReplica.testOutOfOrderDBQWithInPlaceUpdates Error Message: Can not find doc 1 in http://127.0.0.1:58477/solr Stack Trace: java.lang.AssertionError: Can not find doc 1 in http://127.0.0.1:58477/solr at __randomizedtesting.SeedInfo.seed([35824FB124FFF497:B343B75C7BAE2277]:0) at org.junit.Assert.fail(Assert.java:93) at org.junit.Assert.assertTrue(Assert.java:43) at org.junit.Assert.assertNotNull(Assert.java:526) at org.apache.solr.cloud.TestTlogReplica.checkRTG(TestTlogReplica.java:861) at org.apache.solr.cloud.TestTlogReplica.testOutOfOrderDBQWithInPlaceUpdates(TestTlogReplica.java:664) 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 11644 lines...] [junit4] Suite: org.apache.solr.cloud.TestTlogReplica [junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/init-core-data-001 [junit4] 2> 257770 WARN (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=105 numCloses=105 [junit4] 2> 257770 INFO (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=false [junit4] 2> 257774 INFO (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, value=NaN, ssl=NaN, clientAuth=NaN) w/ MAC_OS_X supressed clientAuth [junit4] 2> 257774 INFO (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom [junit4] 2> 257775 INFO (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001 [junit4] 2> 257775 INFO (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER [junit4] 2> 257776 INFO (Thread-218) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0 [junit4] 2> 257776 INFO (Thread-218) [ ] o.a.s.c.ZkTestServer Starting server [junit4] 2> 257780 ERROR (Thread-218) [ ] 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> 257891 INFO (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:58474 [junit4] 2> 257917 INFO (jetty-launcher-180-thread-1) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 [junit4] 2> 257922 INFO (jetty-launcher-180-thread-2) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 [junit4] 2> 257925 INFO (jetty-launcher-180-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2068ca69{/solr,null,AVAILABLE} [junit4] 2> 257926 INFO (jetty-launcher-180-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@21e069d7{HTTP/1.1,[http/1.1]}{127.0.0.1:58476} [junit4] 2> 257926 INFO (jetty-launcher-180-thread-2) [ ] o.e.j.s.Server Started @262931ms [junit4] 2> 257926 INFO (jetty-launcher-180-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=58476} [junit4] 2> 257926 ERROR (jetty-launcher-180-thread-2) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 257930 INFO (jetty-launcher-180-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.1.0 [junit4] 2> 257930 INFO (jetty-launcher-180-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 257930 INFO (jetty-launcher-180-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 257930 INFO (jetty-launcher-180-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-10-04T19:57:33.398Z [junit4] 2> 257933 INFO (jetty-launcher-180-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@46bc12a6{/solr,null,AVAILABLE} [junit4] 2> 257933 INFO (jetty-launcher-180-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7dff4492{HTTP/1.1,[http/1.1]}{127.0.0.1:58477} [junit4] 2> 257933 INFO (jetty-launcher-180-thread-1) [ ] o.e.j.s.Server Started @262938ms [junit4] 2> 257933 INFO (jetty-launcher-180-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=58477} [junit4] 2> 257934 ERROR (jetty-launcher-180-thread-1) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. [junit4] 2> 257939 INFO (jetty-launcher-180-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.1.0 [junit4] 2> 257939 INFO (jetty-launcher-180-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null [junit4] 2> 257939 INFO (jetty-launcher-180-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null, Default config dir: null [junit4] 2> 257939 INFO (jetty-launcher-180-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-10-04T19:57:33.407Z [junit4] 2> 257952 INFO (jetty-launcher-180-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 257967 INFO (jetty-launcher-180-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... [junit4] 2> 257969 INFO (jetty-launcher-180-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:58474/solr [junit4] 2> 257984 INFO (jetty-launcher-180-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:58474/solr [junit4] 2> 258605 INFO (jetty-launcher-180-thread-1) [n:127.0.0.1:58477_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 258607 INFO (jetty-launcher-180-thread-1) [n:127.0.0.1:58477_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:58477_solr [junit4] 2> 258607 INFO (jetty-launcher-180-thread-2) [n:127.0.0.1:58476_solr ] o.a.s.c.Overseer Overseer (id=null) closing [junit4] 2> 258610 INFO (jetty-launcher-180-thread-1) [n:127.0.0.1:58477_solr ] o.a.s.c.Overseer Overseer (id=98772389281595398-127.0.0.1:58477_solr-n_0000000000) starting [junit4] 2> 258612 INFO (jetty-launcher-180-thread-2) [n:127.0.0.1:58476_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58476_solr [junit4] 2> 258618 INFO (zkCallback-192-thread-1-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 258618 INFO (zkCallback-190-thread-1-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) [junit4] 2> 258629 INFO (jetty-launcher-180-thread-1) [n:127.0.0.1:58477_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58477_solr [junit4] 2> 258632 INFO (zkCallback-190-thread-1-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 258632 INFO (zkCallback-192-thread-1-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) [junit4] 2> 258919 INFO (jetty-launcher-180-thread-1) [n:127.0.0.1:58477_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58477.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 258933 INFO (jetty-launcher-180-thread-2) [n:127.0.0.1:58476_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58476.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 258940 INFO (jetty-launcher-180-thread-1) [n:127.0.0.1:58477_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58477.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 258940 INFO (jetty-launcher-180-thread-1) [n:127.0.0.1:58477_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58477.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 258942 INFO (jetty-launcher-180-thread-1) [n:127.0.0.1:58477_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node1/. [junit4] 2> 258945 INFO (jetty-launcher-180-thread-2) [n:127.0.0.1:58476_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58476.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 258945 INFO (jetty-launcher-180-thread-2) [n:127.0.0.1:58476_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58476.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 258946 INFO (jetty-launcher-180-thread-2) [n:127.0.0.1:58476_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node2/. [junit4] 2> 259036 INFO (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2) [junit4] 2> 259038 INFO (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:58474/solr ready [junit4] 2> 259072 INFO (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.c.TestTlogReplica Using legacyCloud?: false [junit4] 2> 259083 INFO (qtp2119444707-1145) [n:127.0.0.1:58476_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :clusterprop with params val=false&name=legacyCloud&action=CLUSTERPROP&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 259103 INFO (qtp2119444707-1145) [n:127.0.0.1:58476_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={val=false&name=legacyCloud&action=CLUSTERPROP&wt=javabin&version=2} status=0 QTime=20 [junit4] 2> 259143 INFO (TEST-TestTlogReplica.testCreateDelete-seed#[35824FB124FFF497]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testCreateDelete {seed=[35824FB124FFF497:2E92BEFDD20F0CA7]} [junit4] 2> 259145 INFO (qtp2119444707-1146) [n:127.0.0.1:58476_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params pullReplicas=0&replicationFactor=0&collection.configName=conf&maxShardsPerNode=100&name=tlog_replica_test_create_delete&nrtReplicas=0&action=CREATE&numShards=2&tlogReplicas=4&wt=javabin&version=2 and sendToOCPQueue=true [junit4] 2> 259152 INFO (OverseerThreadFactory-523-thread-1-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.CreateCollectionCmd Create collection tlog_replica_test_create_delete [junit4] 2> 259153 WARN (OverseerThreadFactory-523-thread-1-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.CreateCollectionCmd Specified number of replicas of 4 on collection tlog_replica_test_create_delete 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> 259286 INFO (OverseerStateUpdate-98772389281595398-127.0.0.1:58477_solr-n_0000000000) [n:127.0.0.1:58477_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_create_delete", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"tlog_replica_test_create_delete_shard1_replica_t1", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:58477/solr";, [junit4] 2> "type":"TLOG"} [junit4] 2> 259293 INFO (OverseerStateUpdate-98772389281595398-127.0.0.1:58477_solr-n_0000000000) [n:127.0.0.1:58477_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_create_delete", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"tlog_replica_test_create_delete_shard1_replica_t2", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:58476/solr";, [junit4] 2> "type":"TLOG"} [junit4] 2> 259305 INFO (OverseerStateUpdate-98772389281595398-127.0.0.1:58477_solr-n_0000000000) [n:127.0.0.1:58477_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_create_delete", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"tlog_replica_test_create_delete_shard1_replica_t4", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:58477/solr";, [junit4] 2> "type":"TLOG"} [junit4] 2> 259314 INFO (OverseerStateUpdate-98772389281595398-127.0.0.1:58477_solr-n_0000000000) [n:127.0.0.1:58477_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_create_delete", [junit4] 2> "shard":"shard1", [junit4] 2> "core":"tlog_replica_test_create_delete_shard1_replica_t6", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:58476/solr";, [junit4] 2> "type":"TLOG"} [junit4] 2> 259324 INFO (OverseerStateUpdate-98772389281595398-127.0.0.1:58477_solr-n_0000000000) [n:127.0.0.1:58477_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_create_delete", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"tlog_replica_test_create_delete_shard2_replica_t8", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:58477/solr";, [junit4] 2> "type":"TLOG"} [junit4] 2> 259330 INFO (OverseerStateUpdate-98772389281595398-127.0.0.1:58477_solr-n_0000000000) [n:127.0.0.1:58477_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_create_delete", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"tlog_replica_test_create_delete_shard2_replica_t10", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:58476/solr";, [junit4] 2> "type":"TLOG"} [junit4] 2> 259342 INFO (OverseerStateUpdate-98772389281595398-127.0.0.1:58477_solr-n_0000000000) [n:127.0.0.1:58477_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_create_delete", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"tlog_replica_test_create_delete_shard2_replica_t13", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:58477/solr";, [junit4] 2> "type":"TLOG"} [junit4] 2> 259347 INFO (OverseerStateUpdate-98772389281595398-127.0.0.1:58477_solr-n_0000000000) [n:127.0.0.1:58477_solr ] o.a.s.c.o.SliceMutator createReplica() { [junit4] 2> "operation":"ADDREPLICA", [junit4] 2> "collection":"tlog_replica_test_create_delete", [junit4] 2> "shard":"shard2", [junit4] 2> "core":"tlog_replica_test_create_delete_shard2_replica_t14", [junit4] 2> "state":"down", [junit4] 2> "base_url":"http://127.0.0.1:58476/solr";, [junit4] 2> "type":"TLOG"} [junit4] 2> 259555 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node5&collection.configName=conf&newCollection=true&name=tlog_replica_test_create_delete_shard1_replica_t2&action=CREATE&numShards=2&collection=tlog_replica_test_create_delete&shard=shard1&wt=javabin&version=2&replicaType=TLOG [junit4] 2> 259556 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 259558 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node9&collection.configName=conf&newCollection=true&name=tlog_replica_test_create_delete_shard1_replica_t6&action=CREATE&numShards=2&collection=tlog_replica_test_create_delete&shard=shard1&wt=javabin&version=2&replicaType=TLOG [junit4] 2> 259561 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node16&collection.configName=conf&newCollection=true&name=tlog_replica_test_create_delete_shard2_replica_t14&action=CREATE&numShards=2&collection=tlog_replica_test_create_delete&shard=shard2&wt=javabin&version=2&replicaType=TLOG [junit4] 2> 259562 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node15&collection.configName=conf&newCollection=true&name=tlog_replica_test_create_delete_shard2_replica_t13&action=CREATE&numShards=2&collection=tlog_replica_test_create_delete&shard=shard2&wt=javabin&version=2&replicaType=TLOG [junit4] 2> 259562 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores [junit4] 2> 259562 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=tlog_replica_test_create_delete_shard1_replica_t1&action=CREATE&numShards=2&collection=tlog_replica_test_create_delete&shard=shard1&wt=javabin&version=2&replicaType=TLOG [junit4] 2> 259563 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node12&collection.configName=conf&newCollection=true&name=tlog_replica_test_create_delete_shard2_replica_t10&action=CREATE&numShards=2&collection=tlog_replica_test_create_delete&shard=shard2&wt=javabin&version=2&replicaType=TLOG [junit4] 2> 259563 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node11&collection.configName=conf&newCollection=true&name=tlog_replica_test_create_delete_shard2_replica_t8&action=CREATE&numShards=2&collection=tlog_replica_test_create_delete&shard=shard2&wt=javabin&version=2&replicaType=TLOG [junit4] 2> 259564 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node7&collection.configName=conf&newCollection=true&name=tlog_replica_test_create_delete_shard1_replica_t4&action=CREATE&numShards=2&collection=tlog_replica_test_create_delete&shard=shard1&wt=javabin&version=2&replicaType=TLOG [junit4] 2> 259722 INFO (zkCallback-192-thread-2-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 259722 INFO (zkCallback-190-thread-1-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 259722 INFO (zkCallback-192-thread-1-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 259722 INFO (zkCallback-190-thread-2-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 260643 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 260654 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 260657 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 260663 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 260676 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 260678 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 260681 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 260684 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.1.0 [junit4] 2> 260722 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.s.IndexSchema [tlog_replica_test_create_delete_shard1_replica_t6] Schema name=minimal [junit4] 2> 260726 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.s.IndexSchema [tlog_replica_test_create_delete_shard2_replica_t8] Schema name=minimal [junit4] 2> 260731 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.s.IndexSchema [tlog_replica_test_create_delete_shard1_replica_t2] Schema name=minimal [junit4] 2> 260732 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.s.IndexSchema [tlog_replica_test_create_delete_shard1_replica_t1] Schema name=minimal [junit4] 2> 260732 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.s.IndexSchema [tlog_replica_test_create_delete_shard2_replica_t13] Schema name=minimal [junit4] 2> 260732 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 260732 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.c.CoreContainer Creating SolrCore 'tlog_replica_test_create_delete_shard1_replica_t6' using configuration from collection tlog_replica_test_create_delete, trusted=true [junit4] 2> 260733 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58476.solr.core.tlog_replica_test_create_delete.shard1.replica_t6' (registry 'solr.core.tlog_replica_test_create_delete.shard1.replica_t6') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 260734 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 260735 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.c.SolrCore [[tlog_replica_test_create_delete_shard1_replica_t6] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node2/tlog_replica_test_create_delete_shard1_replica_t6], dataDir=[/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node2/./tlog_replica_test_create_delete_shard1_replica_t6/data/] [junit4] 2> 260739 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.s.IndexSchema [tlog_replica_test_create_delete_shard1_replica_t4] Schema name=minimal [junit4] 2> 260739 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 260739 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.CoreContainer Creating SolrCore 'tlog_replica_test_create_delete_shard2_replica_t13' using configuration from collection tlog_replica_test_create_delete, trusted=true [junit4] 2> 260739 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 260739 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.CoreContainer Creating SolrCore 'tlog_replica_test_create_delete_shard1_replica_t1' using configuration from collection tlog_replica_test_create_delete, trusted=true [junit4] 2> 260740 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58477.solr.core.tlog_replica_test_create_delete.shard1.replica_t1' (registry 'solr.core.tlog_replica_test_create_delete.shard1.replica_t1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 260740 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58477.solr.core.tlog_replica_test_create_delete.shard2.replica_t13' (registry 'solr.core.tlog_replica_test_create_delete.shard2.replica_t13') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 260740 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 260740 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 260740 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.SolrCore [[tlog_replica_test_create_delete_shard1_replica_t1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node1/tlog_replica_test_create_delete_shard1_replica_t1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node1/./tlog_replica_test_create_delete_shard1_replica_t1/data/] [junit4] 2> 260740 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.SolrCore [[tlog_replica_test_create_delete_shard2_replica_t13] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node1/tlog_replica_test_create_delete_shard2_replica_t13], dataDir=[/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node1/./tlog_replica_test_create_delete_shard2_replica_t13/data/] [junit4] 2> 260742 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 260742 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.c.CoreContainer Creating SolrCore 'tlog_replica_test_create_delete_shard1_replica_t4' using configuration from collection tlog_replica_test_create_delete, trusted=true [junit4] 2> 260743 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58477.solr.core.tlog_replica_test_create_delete.shard1.replica_t4' (registry 'solr.core.tlog_replica_test_create_delete.shard1.replica_t4') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 260743 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 260743 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.c.SolrCore [[tlog_replica_test_create_delete_shard1_replica_t4] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node1/tlog_replica_test_create_delete_shard1_replica_t4], dataDir=[/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node1/./tlog_replica_test_create_delete_shard1_replica_t4/data/] [junit4] 2> 260748 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 260748 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.c.CoreContainer Creating SolrCore 'tlog_replica_test_create_delete_shard2_replica_t8' using configuration from collection tlog_replica_test_create_delete, trusted=true [junit4] 2> 260749 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58477.solr.core.tlog_replica_test_create_delete.shard2.replica_t8' (registry 'solr.core.tlog_replica_test_create_delete.shard2.replica_t8') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 260749 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 260749 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.c.SolrCore [[tlog_replica_test_create_delete_shard2_replica_t8] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node1/tlog_replica_test_create_delete_shard2_replica_t8], dataDir=[/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node1/./tlog_replica_test_create_delete_shard2_replica_t8/data/] [junit4] 2> 260751 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 260751 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.c.CoreContainer Creating SolrCore 'tlog_replica_test_create_delete_shard1_replica_t2' using configuration from collection tlog_replica_test_create_delete, trusted=true [junit4] 2> 260751 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58476.solr.core.tlog_replica_test_create_delete.shard1.replica_t2' (registry 'solr.core.tlog_replica_test_create_delete.shard1.replica_t2') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 260751 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 260751 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.c.SolrCore [[tlog_replica_test_create_delete_shard1_replica_t2] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node2/tlog_replica_test_create_delete_shard1_replica_t2], dataDir=[/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node2/./tlog_replica_test_create_delete_shard1_replica_t2/data/] [junit4] 2> 260755 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.s.IndexSchema [tlog_replica_test_create_delete_shard2_replica_t10] Schema name=minimal [junit4] 2> 260758 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 260758 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.c.CoreContainer Creating SolrCore 'tlog_replica_test_create_delete_shard2_replica_t10' using configuration from collection tlog_replica_test_create_delete, trusted=true [junit4] 2> 260758 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58476.solr.core.tlog_replica_test_create_delete.shard2.replica_t10' (registry 'solr.core.tlog_replica_test_create_delete.shard2.replica_t10') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 260759 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 260759 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.c.SolrCore [[tlog_replica_test_create_delete_shard2_replica_t10] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node2/tlog_replica_test_create_delete_shard2_replica_t10], dataDir=[/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node2/./tlog_replica_test_create_delete_shard2_replica_t10/data/] [junit4] 2> 260762 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.s.IndexSchema [tlog_replica_test_create_delete_shard2_replica_t14] Schema name=minimal [junit4] 2> 260764 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id [junit4] 2> 260764 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.c.CoreContainer Creating SolrCore 'tlog_replica_test_create_delete_shard2_replica_t14' using configuration from collection tlog_replica_test_create_delete, trusted=true [junit4] 2> 260765 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_58476.solr.core.tlog_replica_test_create_delete.shard2.replica_t14' (registry 'solr.core.tlog_replica_test_create_delete.shard2.replica_t14') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@2c11b348 [junit4] 2> 260765 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder [junit4] 2> 260765 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.c.SolrCore [[tlog_replica_test_create_delete_shard2_replica_t14] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node2/tlog_replica_test_create_delete_shard2_replica_t14], dataDir=[/Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001/tempDir-001/node2/./tlog_replica_test_create_delete_shard2_replica_t14/data/] [junit4] 2> 261045 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 261045 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 261059 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 261059 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 261096 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 261096 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 261106 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 261106 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 261118 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 261118 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 261119 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6f38734a[tlog_replica_test_create_delete_shard1_replica_t1] main] [junit4] 2> 261121 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 261121 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 261129 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.s.SolrIndexSearcher Opening [Searcher@d76af24[tlog_replica_test_create_delete_shard2_replica_t13] main] [junit4] 2> 261131 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 261132 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 261137 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 261137 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580358232026644480 [junit4] 2> 261139 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 261139 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 261139 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 261149 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard1: total=4 found=1 timeoutin=9999ms [junit4] 2> 261153 INFO (searcherExecutor-530-thread-1-processing-n:127.0.0.1:58477_solr x:tlog_replica_test_create_delete_shard1_replica_t1 s:shard1 c:tlog_replica_test_create_delete r:core_node3) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.SolrCore [tlog_replica_test_create_delete_shard1_replica_t1] Registered new searcher Searcher@6f38734a[tlog_replica_test_create_delete_shard1_replica_t1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 261154 INFO (searcherExecutor-529-thread-1-processing-n:127.0.0.1:58477_solr x:tlog_replica_test_create_delete_shard2_replica_t13 s:shard2 c:tlog_replica_test_create_delete r:core_node15) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.SolrCore [tlog_replica_test_create_delete_shard2_replica_t13] Registered new searcher Searcher@d76af24[tlog_replica_test_create_delete_shard2_replica_t13] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 261154 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580358232044470272 [junit4] 2> 261155 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 261155 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 261166 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard2: total=4 found=1 timeoutin=9999ms [junit4] 2> 261167 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 261167 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 261172 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.s.SolrIndexSearcher Opening [Searcher@6d008334[tlog_replica_test_create_delete_shard1_replica_t4] main] [junit4] 2> 261183 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 261184 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 261184 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 261184 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 261186 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.s.SolrIndexSearcher Opening [Searcher@31e13cee[tlog_replica_test_create_delete_shard1_replica_t2] main] [junit4] 2> 261188 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 261188 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 261189 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 261189 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580358232081170432 [junit4] 2> 261191 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 261191 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 261194 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 261200 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 261200 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 261202 INFO (searcherExecutor-531-thread-1-processing-n:127.0.0.1:58477_solr x:tlog_replica_test_create_delete_shard1_replica_t4 s:shard1 c:tlog_replica_test_create_delete r:core_node7) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.c.SolrCore [tlog_replica_test_create_delete_shard1_replica_t4] Registered new searcher Searcher@6d008334[tlog_replica_test_create_delete_shard1_replica_t4] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 261203 INFO (searcherExecutor-533-thread-1-processing-n:127.0.0.1:58476_solr x:tlog_replica_test_create_delete_shard1_replica_t2 s:shard1 c:tlog_replica_test_create_delete r:core_node5) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.c.SolrCore [tlog_replica_test_create_delete_shard1_replica_t2] Registered new searcher Searcher@31e13cee[tlog_replica_test_create_delete_shard1_replica_t2] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 261203 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580358232095850496 [junit4] 2> 261204 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 261204 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 261208 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 261208 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 261211 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 261211 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 261216 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.s.SolrIndexSearcher Opening [Searcher@72a03733[tlog_replica_test_create_delete_shard1_replica_t6] main] [junit4] 2> 261217 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.s.SolrIndexSearcher Opening [Searcher@7049bad6[tlog_replica_test_create_delete_shard2_replica_t14] main] [junit4] 2> 261217 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.s.SolrIndexSearcher Opening [Searcher@36d6d4[tlog_replica_test_create_delete_shard2_replica_t8] main] [junit4] 2> 261218 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog [junit4] 2> 261219 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536 [junit4] 2> 261219 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 261219 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 261220 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 261220 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 261220 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 261220 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 261221 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580358232114724864 [junit4] 2> 261221 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580358232114724864 [junit4] 2> 261224 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.u.CommitTracker Hard AutoCommit: disabled [junit4] 2> 261222 INFO (searcherExecutor-528-thread-1-processing-n:127.0.0.1:58476_solr x:tlog_replica_test_create_delete_shard1_replica_t6 s:shard1 c:tlog_replica_test_create_delete r:core_node9) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.c.SolrCore [tlog_replica_test_create_delete_shard1_replica_t6] Registered new searcher Searcher@72a03733[tlog_replica_test_create_delete_shard1_replica_t6] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 261222 INFO (searcherExecutor-532-thread-1-processing-n:127.0.0.1:58477_solr x:tlog_replica_test_create_delete_shard2_replica_t8 s:shard2 c:tlog_replica_test_create_delete r:core_node11) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.c.SolrCore [tlog_replica_test_create_delete_shard2_replica_t8] Registered new searcher Searcher@36d6d4[tlog_replica_test_create_delete_shard2_replica_t8] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 261227 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 261232 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.u.CommitTracker Soft AutoCommit: disabled [junit4] 2> 261233 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 261235 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 261235 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580358232129404928 [junit4] 2> 261237 INFO (searcherExecutor-535-thread-1-processing-n:127.0.0.1:58476_solr x:tlog_replica_test_create_delete_shard2_replica_t14 s:shard2 c:tlog_replica_test_create_delete r:core_node16) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.c.SolrCore [tlog_replica_test_create_delete_shard2_replica_t14] Registered new searcher Searcher@7049bad6[tlog_replica_test_create_delete_shard2_replica_t14] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 261239 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.s.SolrIndexSearcher Opening [Searcher@6e1ae[tlog_replica_test_create_delete_shard2_replica_t10] main] [junit4] 2> 261242 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf [junit4] 2> 261242 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf [junit4] 2> 261243 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 261244 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1580358232137793536 [junit4] 2> 261255 INFO (searcherExecutor-534-thread-1-processing-n:127.0.0.1:58476_solr x:tlog_replica_test_create_delete_shard2_replica_t10 s:shard2 c:tlog_replica_test_create_delete r:core_node12) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.c.SolrCore [tlog_replica_test_create_delete_shard2_replica_t10] Registered new searcher Searcher@6e1ae[tlog_replica_test_create_delete_shard2_replica_t10] main{ExitableDirectoryReader(UninvertingDirectoryReader())} [junit4] 2> 261278 INFO (zkCallback-190-thread-1-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 261278 INFO (zkCallback-190-thread-2-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 261279 INFO (zkCallback-192-thread-2-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 261279 INFO (zkCallback-192-thread-1-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 261651 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 261651 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 261651 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:58477/solr/tlog_replica_test_create_delete_shard1_replica_t1/ [junit4] 2> 261652 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.u.PeerSync PeerSync: core=tlog_replica_test_create_delete_shard1_replica_t1 url=http://127.0.0.1:58477/solr START replicas=[http://127.0.0.1:58476/solr/tlog_replica_test_create_delete_shard1_replica_t2/, http://127.0.0.1:58477/solr/tlog_replica_test_create_delete_shard1_replica_t4/, http://127.0.0.1:58476/solr/tlog_replica_test_create_delete_shard1_replica_t6/] nUpdates=100 [junit4] 2> 261692 INFO (qtp149293186-1159) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.c.S.Request [tlog_replica_test_create_delete_shard1_replica_t4] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=18 [junit4] 2> 261694 INFO (qtp2119444707-1143) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.c.S.Request [tlog_replica_test_create_delete_shard1_replica_t2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=2 [junit4] 2> 261694 INFO (qtp2119444707-1145) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.c.S.Request [tlog_replica_test_create_delete_shard1_replica_t6] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=1 [junit4] 2> 261695 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue. [junit4] 2> 261695 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync [junit4] 2> 261695 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:58477/solr/tlog_replica_test_create_delete_shard2_replica_t13/ [junit4] 2> 261696 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.u.PeerSync PeerSync: core=tlog_replica_test_create_delete_shard2_replica_t13 url=http://127.0.0.1:58477/solr START replicas=[http://127.0.0.1:58477/solr/tlog_replica_test_create_delete_shard2_replica_t8/, http://127.0.0.1:58476/solr/tlog_replica_test_create_delete_shard2_replica_t10/, http://127.0.0.1:58476/solr/tlog_replica_test_create_delete_shard2_replica_t14/] nUpdates=100 [junit4] 2> 261702 INFO (qtp149293186-1152) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.c.S.Request [tlog_replica_test_create_delete_shard2_replica_t8] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=3 [junit4] 2> 261702 INFO (qtp2119444707-1233) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.c.S.Request [tlog_replica_test_create_delete_shard2_replica_t14] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=3 [junit4] 2> 261710 INFO (qtp2119444707-1233) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.c.S.Request [tlog_replica_test_create_delete_shard2_replica_t10] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=7 [junit4] 2> 261966 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.u.PeerSync PeerSync: core=tlog_replica_test_create_delete_shard1_replica_t1 url=http://127.0.0.1:58477/solr DONE. We have no versions. sync failed. [junit4] 2> 261966 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate [junit4] 2> 261966 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] 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> 261966 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 261969 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.ZkController tlog_replica_test_create_delete_shard1_replica_t1 stopping background replication from leader [junit4] 2> 261974 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:58477/solr/tlog_replica_test_create_delete_shard1_replica_t1/ shard1 [junit4] 2> 261999 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.u.PeerSync PeerSync: core=tlog_replica_test_create_delete_shard2_replica_t13 url=http://127.0.0.1:58477/solr DONE. We have no versions. sync failed. [junit4] 2> 261999 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate [junit4] 2> 261999 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] 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> 261999 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR [junit4] 2> 262000 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.ZkController tlog_replica_test_create_delete_shard2_replica_t13 stopping background replication from leader [junit4] 2> 262006 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:58477/solr/tlog_replica_test_create_delete_shard2_replica_t13/ shard2 [junit4] 2> 262113 INFO (zkCallback-190-thread-1-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 262113 INFO (zkCallback-190-thread-2-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 262113 INFO (zkCallback-192-thread-1-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 262113 INFO (zkCallback-192-thread-2-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 262119 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 262121 INFO (qtp149293186-1154) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node15 x:tlog_replica_test_create_delete_shard2_replica_t13] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node15&collection.configName=conf&newCollection=true&name=tlog_replica_test_create_delete_shard2_replica_t13&action=CREATE&numShards=2&collection=tlog_replica_test_create_delete&shard=shard2&wt=javabin&version=2&replicaType=TLOG} status=0 QTime=2559 [junit4] 2> 262150 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.c.ZkController I am the leader, no recovery necessary [junit4] 2> 262154 INFO (qtp149293186-1157) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node3 x:tlog_replica_test_create_delete_shard1_replica_t1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node3&collection.configName=conf&newCollection=true&name=tlog_replica_test_create_delete_shard1_replica_t1&action=CREATE&numShards=2&collection=tlog_replica_test_create_delete&shard=shard1&wt=javabin&version=2&replicaType=TLOG} status=0 QTime=2591 [junit4] 2> 262224 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.c.ZkController tlog_replica_test_create_delete_shard1_replica_t4 starting background replication from leader [junit4] 2> 262225 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard1 r:core_node7 x:tlog_replica_test_create_delete_shard1_replica_t4] o.a.s.c.ReplicateFromLeader Will start replication from leader with poll interval: 00:00:03 [junit4] 2> 262227 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.c.ZkController tlog_replica_test_create_delete_shard1_replica_t2 starting background replication from leader [junit4] 2> 262227 INFO (qtp2119444707-1147) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node5 x:tlog_replica_test_create_delete_shard1_replica_t2] o.a.s.c.ReplicateFromLeader Will start replication from leader with poll interval: 00:00:03 [junit4] 2> 262242 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.c.ZkController tlog_replica_test_create_delete_shard2_replica_t8 starting background replication from leader [junit4] 2> 262242 INFO (qtp149293186-1156) [n:127.0.0.1:58477_solr c:tlog_replica_test_create_delete s:shard2 r:core_node11 x:tlog_replica_test_create_delete_shard2_replica_t8] o.a.s.c.ReplicateFromLeader Will start replication from leader with poll interval: 00:00:03 [junit4] 2> 262243 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.c.ZkController tlog_replica_test_create_delete_shard1_replica_t6 starting background replication from leader [junit4] 2> 262243 INFO (qtp2119444707-1148) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard1 r:core_node9 x:tlog_replica_test_create_delete_shard1_replica_t6] o.a.s.c.ReplicateFromLeader Will start replication from leader with poll interval: 00:00:03 [junit4] 2> 262244 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.c.ZkController tlog_replica_test_create_delete_shard2_replica_t14 starting background replication from leader [junit4] 2> 262245 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.c.ReplicateFromLeader Will start replication from leader with poll interval: 00:00:03 [junit4] 2> 262264 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.c.ZkController tlog_replica_test_create_delete_shard2_replica_t10 starting background replication from leader [junit4] 2> 262264 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.c.ReplicateFromLeader Will start replication from leader with poll interval: 00:00:03 [junit4] 2> 262265 INFO (zkCallback-190-thread-2-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 262265 INFO (zkCallback-190-thread-1-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 262265 INFO (zkCallback-192-thread-2-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 262265 INFO (zkCallback-192-thread-1-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/tlog_replica_test_create_delete/state.json] for collection [tlog_replica_test_create_delete] has occurred - updating... (live nodes size: [2]) [junit4] 2> 262283 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 3000ms [junit4] 2> 262283 INFO (qtp2119444707-1150) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 262283 INFO (indexFetcher-574-thread-1) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node12 x:tlog_replica_test_create_delete_shard2_replica_t10] o.a.s.h.IndexFetcher Updated masterUrl to http://127.0.0.1:58477/solr/tlog_replica_test_create_delete_shard2_replica_t13/ [junit4] 2> 262283 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 3000ms [junit4] 2> 262284 INFO (qtp2119444707-1149) [n:127.0.0.1:58476_solr c:tlog_replica_test_create_delete s:shard2 r:core_node16 x:tlog_replica_test_create_delete_shard2_replica_t14] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms. [junit4] 2> 262284 INFO (qtp149293186-1158) [n:127.0.0.1:58477_solr c:tlog_replica_ [...truncated too long message...] service url = null, agent id = null] for registry solr.core.tlog_replica_test_out_of_order_db_qwith_in_place_updates.shard1.replica_t1 / com.codahale.metrics.MetricRegistry@cb7c360 [junit4] 2> 383000 INFO (jetty-closer-181-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null [junit4] 2> 383000 INFO (jetty-closer-181-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@4f5cb1a3: rootName = solr_58476, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@6e8581a3 [junit4] 2> 383002 INFO (jetty-closer-181-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null [junit4] 2> 383004 WARN (zkCallback-249-thread-2-processing-n:127.0.0.1:58476_solr) [n:127.0.0.1:58476_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 383006 INFO (jetty-closer-181-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@f9e8231{/solr,null,UNAVAILABLE} [junit4] 2> 383006 INFO (zkCallback-243-thread-1-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1) [junit4] 2> 383008 INFO (coreCloseExecutor-1006-thread-1) [n:127.0.0.1:58477_solr c:tlog_replica_test_out_of_order_db_qwith_in_place_updates s:shard1 r:core_node3 x:tlog_replica_test_out_of_order_db_qwith_in_place_updates_shard1_replica_t1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.tlog_replica_test_out_of_order_db_qwith_in_place_updates.shard1.leader, tag=535344016 [junit4] 2> 383011 INFO (jetty-closer-181-thread-1) [ ] o.a.s.c.Overseer Overseer (id=98772389281595418-127.0.0.1:58477_solr-n_0000000007) closing [junit4] 2> 383011 INFO (OverseerStateUpdate-98772389281595418-127.0.0.1:58477_solr-n_0000000007) [n:127.0.0.1:58477_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:58477_solr [junit4] 2> 383013 WARN (zkCallback-243-thread-1-processing-n:127.0.0.1:58477_solr) [n:127.0.0.1:58477_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes] [junit4] 2> 383868 ERROR (coreZkRegister-964-thread-1-processing-n:127.0.0.1:58477_solr x:tlog_replica_test_out_of_order_db_qwith_in_place_updates_shard1_replica_t1 s:shard1 c:tlog_replica_test_out_of_order_db_qwith_in_place_updates r:core_node3) [n:127.0.0.1:58477_solr c:tlog_replica_test_out_of_order_db_qwith_in_place_updates s:shard1 r:core_node3 x:tlog_replica_test_out_of_order_db_qwith_in_place_updates_shard1_replica_t1] o.a.s.c.ZkController Error getting leader from zk [junit4] 2> org.apache.solr.common.SolrException: CoreContainer is closed [junit4] 2> at org.apache.solr.cloud.ZkController.getLeaderProps(ZkController.java:1143) [junit4] 2> at org.apache.solr.cloud.ZkController.getLeaderProps(ZkController.java:1110) [junit4] 2> at org.apache.solr.cloud.ZkController.getLeader(ZkController.java:1066) [junit4] 2> at org.apache.solr.cloud.ZkController.register(ZkController.java:971) [junit4] 2> at org.apache.solr.cloud.ZkController.register(ZkController.java:906) [junit4] 2> at org.apache.solr.core.ZkContainer.lambda$registerInZk$0(ZkContainer.java:181) [junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] 2> at java.lang.Thread.run(Thread.java:748) [junit4] 2> 383869 ERROR (coreZkRegister-964-thread-1-processing-n:127.0.0.1:58477_solr x:tlog_replica_test_out_of_order_db_qwith_in_place_updates_shard1_replica_t1 s:shard1 c:tlog_replica_test_out_of_order_db_qwith_in_place_updates r:core_node3) [n:127.0.0.1:58477_solr c:tlog_replica_test_out_of_order_db_qwith_in_place_updates s:shard1 r:core_node3 x:tlog_replica_test_out_of_order_db_qwith_in_place_updates_shard1_replica_t1] o.a.s.c.ZkContainer :org.apache.solr.common.SolrException: Error getting leader from zk for shard shard1 [junit4] 2> at org.apache.solr.cloud.ZkController.getLeader(ZkController.java:1099) [junit4] 2> at org.apache.solr.cloud.ZkController.register(ZkController.java:971) [junit4] 2> at org.apache.solr.cloud.ZkController.register(ZkController.java:906) [junit4] 2> at org.apache.solr.core.ZkContainer.lambda$registerInZk$0(ZkContainer.java:181) [junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [junit4] 2> at java.lang.Thread.run(Thread.java:748) [junit4] 2> Caused by: org.apache.solr.common.SolrException: CoreContainer is closed [junit4] 2> at org.apache.solr.cloud.ZkController.getLeaderProps(ZkController.java:1143) [junit4] 2> at org.apache.solr.cloud.ZkController.getLeaderProps(ZkController.java:1110) [junit4] 2> at org.apache.solr.cloud.ZkController.getLeader(ZkController.java:1066) [junit4] 2> ... 7 more [junit4] 2> [junit4] 2> 383869 INFO (jetty-closer-181-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@2b8690b4{/solr,null,UNAVAILABLE} [junit4] 2> 383870 ERROR (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] 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> 383870 INFO (SUITE-TestTlogReplica-seed#[35824FB124FFF497]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:58474 58474 [junit4] 2> 383886 INFO (Thread-218) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:58474 58474 [junit4] 2> 384049 WARN (Thread-218) [ ] o.a.s.c.ZkTestServer Watch limit violations: [junit4] 2> Maximum concurrent create/delete watches above limit: [junit4] 2> [junit4] 2> 33 /solr/configs/conf [junit4] 2> 10 /solr/aliases.json [junit4] 2> 9 /solr/security.json [junit4] 2> 3 /solr/clusterprops.json [junit4] 2> [junit4] 2> Maximum concurrent data watches above limit: [junit4] 2> [junit4] 2> 46 /solr/collections/tlog_replica_test_recovery/state.json [junit4] 2> 28 /solr/collections/tlog_replica_test_create_delete/state.json [junit4] 2> 26 /solr/collections/tlog_replica_test_remove_leader/state.json [junit4] 2> 26 /solr/collections/tlog_replica_test_kill_tlog_replica/state.json [junit4] 2> 26 /solr/collections/tlog_replica_test_basic_leader_election/state.json [junit4] 2> 25 /solr/collections/tlog_replica_test_kill_leader/state.json [junit4] 2> 25 /solr/collections/tlog_replica_test_add_remove_tlog_replica/state.json [junit4] 2> 21 /solr/collections/tlog_replica_test_out_of_order_db_qwith_in_place_updates/state.json [junit4] 2> 15 /solr/collections/tlog_replica_test_add_docs/state.json [junit4] 2> 15 /solr/collections/tlog_replica_test_real_time_get/state.json [junit4] 2> 15 /solr/collections/tlog_replica_test_only_leader_indexes/state.json [junit4] 2> 15 /solr/collections/tlog_replica_test_delete_by_id/state.json [junit4] 2> 10 /solr/clusterstate.json [junit4] 2> 10 /solr/clusterprops.json [junit4] 2> 6 /solr/overseer_elect/election/98772389281595396-127.0.0.1:58476_solr-n_0000000001 [junit4] 2> 4 /solr/collections/tlog_replica_test_recovery/leader_elect/shard1/election/98772389281595396-core_node4-n_0000000000 [junit4] 2> 2 /solr/collections/tlog_replica_test_create_delete/leader_elect/shard1/election/98772389281595398-core_node7-n_0000000001 [junit4] 2> 2 /solr/collections/tlog_replica_test_kill_tlog_replica/leader_elect/shard1/election/98772389281595396-core_node4-n_0000000000 [junit4] 2> [junit4] 2> Maximum concurrent children watches above limit: [junit4] 2> [junit4] 2> 10 /solr/collections [junit4] 2> 3 /solr/overseer/queue [junit4] 2> 3 /solr/live_nodes [junit4] 2> 3 /solr/overseer/collection-queue-work [junit4] 2> [junit4] 2> NOTE: leaving temporary files on disk at: /Users/jenkins/workspace/Lucene-Solr-7.x-MacOSX/solr/build/solr-core/test/J1/temp/solr.cloud.TestTlogReplica_35824FB124FFF497-001 [junit4] 2> Oct 04, 2017 7:59:39 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks [junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s). [junit4] 2> NOTE: test params are: codec=Lucene70, sim=RandomSimilarity(queryNorm=false): {}, locale=sr-RS, timezone=Asia/Ashkhabad [junit4] 2> NOTE: Mac OS X 10.11.6 x86_64/Oracle Corporation 1.8.0_144 (64-bit)/cpus=3,threads=1,free=240061200,total=536870912 [junit4] 2> NOTE: All tests run in this JVM: [BadIndexSchemaTest, TestClassicSimilarityFactory, ParsingFieldUpdateProcessorsTest, PolyFieldTest, TestDistribIDF, TestSolr4Spatial, MoveReplicaHDFSUlogDirTest, ClassificationUpdateProcessorFactoryTest, TestStressInPlaceUpdates, BasicZkTest, TestJettySolrRunner, TestAddFieldRealTimeGet, SolrCoreCheckLockOnStartupTest, TestCharFilters, ClassificationUpdateProcessorTest, TestSearchPerf, OutOfBoxZkACLAndCredentialsProvidersTest, TestDocBasedVersionConstraints, DistributedVersionInfoTest, TestTlogReplica] [junit4] Completed [53/734 (1!)] on J1 in 126.85s, 13 tests, 1 failure <<< FAILURES! [...truncated 49189 lines...]
--------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org
