You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2016/12/09 13:58:26 UTC
[JENKINS] Lucene-Solr-master-MacOSX (64bit/jdk1.8.0) - Build # 3698
- Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-master-MacOSX/3698/
Java: 64bit/jdk1.8.0 -XX:-UseCompressedOops -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: org.apache.solr.cloud.DocValuesNotIndexedTest.testGroupingDVOnly
Error Message:
Unexpected number of elements in the group for intGSF: 5
Stack Trace:
java.lang.AssertionError: Unexpected number of elements in the group for intGSF: 5
at __randomizedtesting.SeedInfo.seed([54DB92C93207C57F:CF60FC917F5FF721]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.DocValuesNotIndexedTest.testGroupingDVOnly(DocValuesNotIndexedTest.java:371)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
at 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:367)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:811)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:462)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 10753 lines...]
[junit4] Suite: org.apache.solr.cloud.DocValuesNotIndexedTest
[junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/init-core-data-001
[junit4] 2> 183942 INFO (SUITE-DocValuesNotIndexedTest-seed#[54DB92C93207C57F]-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> 183943 INFO (SUITE-DocValuesNotIndexedTest-seed#[54DB92C93207C57F]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001
[junit4] 2> 183943 INFO (SUITE-DocValuesNotIndexedTest-seed#[54DB92C93207C57F]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 183943 INFO (Thread-287) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 183943 INFO (Thread-287) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 184052 INFO (SUITE-DocValuesNotIndexedTest-seed#[54DB92C93207C57F]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:51726
[junit4] 2> 184074 INFO (jetty-launcher-214-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 184074 INFO (jetty-launcher-214-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 184077 INFO (jetty-launcher-214-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@6cf1565{/solr,null,AVAILABLE}
[junit4] 2> 184078 INFO (jetty-launcher-214-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@f63ab84{/solr,null,AVAILABLE}
[junit4] 2> 184080 INFO (jetty-launcher-214-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@137af0fc{HTTP/1.1,[http/1.1]}{127.0.0.1:51728}
[junit4] 2> 184080 INFO (jetty-launcher-214-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7d64b42f{HTTP/1.1,[http/1.1]}{127.0.0.1:51729}
[junit4] 2> 184080 INFO (jetty-launcher-214-thread-1) [ ] o.e.j.s.Server Started @191755ms
[junit4] 2> 184080 INFO (jetty-launcher-214-thread-2) [ ] o.e.j.s.Server Started @191755ms
[junit4] 2> 184081 INFO (jetty-launcher-214-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=51729}
[junit4] 2> 184081 INFO (jetty-launcher-214-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=51728}
[junit4] 2> 184081 ERROR (jetty-launcher-214-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 184081 ERROR (jetty-launcher-214-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 184081 INFO (jetty-launcher-214-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.0.0
[junit4] 2> 184081 INFO (jetty-launcher-214-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.0.0
[junit4] 2> 184081 INFO (jetty-launcher-214-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 184081 INFO (jetty-launcher-214-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 184081 INFO (jetty-launcher-214-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 184081 INFO (jetty-launcher-214-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-09T12:45:28.241Z
[junit4] 2> 184081 INFO (jetty-launcher-214-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 184082 INFO (jetty-launcher-214-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-09T12:45:28.242Z
[junit4] 2> 184087 INFO (jetty-launcher-214-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 184087 INFO (jetty-launcher-214-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 184101 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x158e39deeaa0002, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 184105 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x158e39deeaa0001, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 184106 INFO (jetty-launcher-214-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:51726/solr
[junit4] 2> 184107 INFO (jetty-launcher-214-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:51726/solr
[junit4] 2> 184114 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x158e39deeaa0004, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 184164 INFO (jetty-launcher-214-thread-1) [n:127.0.0.1:51728_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:51728_solr
[junit4] 2> 184165 INFO (jetty-launcher-214-thread-2) [n:127.0.0.1:51729_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51729_solr
[junit4] 2> 184166 INFO (jetty-launcher-214-thread-1) [n:127.0.0.1:51728_solr ] o.a.s.c.Overseer Overseer (id=97077659441954822-127.0.0.1:51728_solr-n_0000000000) starting
[junit4] 2> 184169 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 184169 INFO (zkCallback-225-thread-1-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 184184 INFO (jetty-launcher-214-thread-1) [n:127.0.0.1:51728_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51728_solr
[junit4] 2> 184187 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 184187 INFO (zkCallback-225-thread-1-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 184242 INFO (jetty-launcher-214-thread-1) [n:127.0.0.1:51728_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node1/.
[junit4] 2> 184328 INFO (jetty-launcher-214-thread-2) [n:127.0.0.1:51729_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/.
[junit4] 2> 184343 INFO (SUITE-DocValuesNotIndexedTest-seed#[54DB92C93207C57F]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 184345 INFO (SUITE-DocValuesNotIndexedTest-seed#[54DB92C93207C57F]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:51726/solr ready
[junit4] 2> 184358 INFO (qtp1327055148-1335) [n:127.0.0.1:51728_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf1&maxShardsPerNode=2&name=dv_coll&action=CREATE&numShards=4&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 184363 INFO (OverseerThreadFactory-857-thread-1-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.c.CreateCollectionCmd Create collection dv_coll
[junit4] 2> 184479 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&newCollection=true&name=dv_coll_shard2_replica1&action=CREATE&numShards=4&collection=dv_coll&shard=shard2&wt=javabin&version=2
[junit4] 2> 184481 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&newCollection=true&name=dv_coll_shard3_replica1&action=CREATE&numShards=4&collection=dv_coll&shard=shard3&wt=javabin&version=2
[junit4] 2> 184481 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&newCollection=true&name=dv_coll_shard4_replica1&action=CREATE&numShards=4&collection=dv_coll&shard=shard4&wt=javabin&version=2
[junit4] 2> 184484 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf1&newCollection=true&name=dv_coll_shard1_replica1&action=CREATE&numShards=4&collection=dv_coll&shard=shard1&wt=javabin&version=2
[junit4] 2> 184610 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/dv_coll/state.json] for collection [dv_coll] has occurred - updating... (live nodes size: [2])
[junit4] 2> 184610 INFO (zkCallback-225-thread-2-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/dv_coll/state.json] for collection [dv_coll] has occurred - updating... (live nodes size: [2])
[junit4] 2> 185531 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 x:dv_coll_shard3_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 185538 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 x:dv_coll_shard2_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 185539 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 x:dv_coll_shard4_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 185551 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 x:dv_coll_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 185591 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 x:dv_coll_shard1_replica1] o.a.s.s.IndexSchema [dv_coll_shard1_replica1] Schema name=minimal
[junit4] 2> 185592 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 x:dv_coll_shard2_replica1] o.a.s.s.IndexSchema [dv_coll_shard2_replica1] Schema name=minimal
[junit4] 2> 185601 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 x:dv_coll_shard1_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 185601 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 x:dv_coll_shard2_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 185603 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 x:dv_coll_shard2_replica1] o.a.s.c.CoreContainer Creating SolrCore 'dv_coll_shard2_replica1' using configuration from collection dv_coll
[junit4] 2> 185603 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 x:dv_coll_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'dv_coll_shard1_replica1' using configuration from collection dv_coll
[junit4] 2> 185604 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SolrCore [[dv_coll_shard2_replica1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node1/dv_coll_shard2_replica1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node1/./dv_coll_shard2_replica1/data/]
[junit4] 2> 185604 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [[dv_coll_shard1_replica1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/dv_coll_shard1_replica1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/./dv_coll_shard1_replica1/data/]
[junit4] 2> 185603 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 x:dv_coll_shard4_replica1] o.a.s.s.IndexSchema [dv_coll_shard4_replica1] Schema name=minimal
[junit4] 2> 185605 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 x:dv_coll_shard3_replica1] o.a.s.s.IndexSchema [dv_coll_shard3_replica1] Schema name=minimal
[junit4] 2> 185612 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 x:dv_coll_shard4_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 185612 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 x:dv_coll_shard3_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 185614 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 x:dv_coll_shard4_replica1] o.a.s.c.CoreContainer Creating SolrCore 'dv_coll_shard4_replica1' using configuration from collection dv_coll
[junit4] 2> 185614 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 x:dv_coll_shard3_replica1] o.a.s.c.CoreContainer Creating SolrCore 'dv_coll_shard3_replica1' using configuration from collection dv_coll
[junit4] 2> 185617 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.SolrCore [[dv_coll_shard4_replica1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node1/dv_coll_shard4_replica1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node1/./dv_coll_shard4_replica1/data/]
[junit4] 2> 185617 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SolrCore [[dv_coll_shard3_replica1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/dv_coll_shard3_replica1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/./dv_coll_shard3_replica1/data/]
[junit4] 2> 185637 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 185637 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 185639 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 185639 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 185640 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 185640 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 185642 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 185643 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 185646 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 185646 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 185647 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 185647 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 185648 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@4e357f0c[dv_coll_shard2_replica1] main]
[junit4] 2> 185648 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@506cd3d2[dv_coll_shard4_replica1] main]
[junit4] 2> 185650 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 185650 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 185651 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 185651 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema
[junit4] 2> 185651 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 185651 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema
[junit4] 2> 185653 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 0 is already the latest
[junit4] 2> 185653 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 185654 INFO (searcherExecutor-862-thread-1-processing-n:127.0.0.1:51728_solr x:dv_coll_shard2_replica1 s:shard2 c:dv_coll r:core_node1) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SolrCore [dv_coll_shard2_replica1] Registered new searcher Searcher@4e357f0c[dv_coll_shard2_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 185654 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 0 is already the latest
[junit4] 2> 185654 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 185654 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1553242552862244864
[junit4] 2> 185654 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 185654 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 185690 INFO (searcherExecutor-864-thread-1-processing-n:127.0.0.1:51728_solr x:dv_coll_shard4_replica1 s:shard4 c:dv_coll r:core_node2) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.SolrCore [dv_coll_shard4_replica1] Registered new searcher Searcher@506cd3d2[dv_coll_shard4_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 185690 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1553242552899993600
[junit4] 2> 185695 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 185696 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 185704 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 185704 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 185704 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/
[junit4] 2> 185704 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 185704 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SyncStrategy http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/ has no replicas
[junit4] 2> 185708 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@4721c4dd[dv_coll_shard1_replica1] main]
[junit4] 2> 185713 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 185714 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 185714 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema
[junit4] 2> 185718 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 185718 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 185718 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:51728/solr/dv_coll_shard4_replica1/
[junit4] 2> 185718 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 185720 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.SyncStrategy http://127.0.0.1:51728/solr/dv_coll_shard4_replica1/ has no replicas
[junit4] 2> 185720 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 0 is already the latest
[junit4] 2> 185720 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 185721 INFO (searcherExecutor-863-thread-1-processing-n:127.0.0.1:51729_solr x:dv_coll_shard1_replica1 s:shard1 c:dv_coll r:core_node4) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [dv_coll_shard1_replica1] Registered new searcher Searcher@4721c4dd[dv_coll_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 185721 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1553242552932499456
[junit4] 2> 185728 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@421a11c[dv_coll_shard3_replica1] main]
[junit4] 2> 185730 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 185731 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 185731 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema
[junit4] 2> 185733 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 0 is already the latest
[junit4] 2> 185733 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 185733 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1553242552945082368
[junit4] 2> 185733 INFO (searcherExecutor-865-thread-1-processing-n:127.0.0.1:51729_solr x:dv_coll_shard3_replica1 s:shard3 c:dv_coll r:core_node3) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SolrCore [dv_coll_shard3_replica1] Registered new searcher Searcher@421a11c[dv_coll_shard3_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 185744 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:51728/solr/dv_coll_shard4_replica1/ shard4
[junit4] 2> 185752 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 185752 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 185752 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:51729/solr/dv_coll_shard3_replica1/
[junit4] 2> 185753 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 185753 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SyncStrategy http://127.0.0.1:51729/solr/dv_coll_shard3_replica1/ has no replicas
[junit4] 2> 185764 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 185766 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 185766 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:51729/solr/dv_coll_shard1_replica1/
[junit4] 2> 185766 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 185766 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SyncStrategy http://127.0.0.1:51729/solr/dv_coll_shard1_replica1/ has no replicas
[junit4] 2> 185765 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:51729/solr/dv_coll_shard3_replica1/ shard3
[junit4] 2> 185770 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/ shard2
[junit4] 2> 185776 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:51729/solr/dv_coll_shard1_replica1/ shard1
[junit4] 2> 185891 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/dv_coll/state.json] for collection [dv_coll] has occurred - updating... (live nodes size: [2])
[junit4] 2> 185891 INFO (zkCallback-225-thread-3-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/dv_coll/state.json] for collection [dv_coll] has occurred - updating... (live nodes size: [2])
[junit4] 2> 185901 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 185906 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&name=dv_coll_shard4_replica1&action=CREATE&numShards=4&collection=dv_coll&shard=shard4&wt=javabin&version=2} status=0 QTime=1424
[junit4] 2> 185942 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 185942 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 185942 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 185951 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&name=dv_coll_shard1_replica1&action=CREATE&numShards=4&collection=dv_coll&shard=shard1&wt=javabin&version=2} status=0 QTime=1467
[junit4] 2> 185953 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&name=dv_coll_shard3_replica1&action=CREATE&numShards=4&collection=dv_coll&shard=shard3&wt=javabin&version=2} status=0 QTime=1471
[junit4] 2> 185957 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf1&newCollection=true&name=dv_coll_shard2_replica1&action=CREATE&numShards=4&collection=dv_coll&shard=shard2&wt=javabin&version=2} status=0 QTime=1477
[junit4] 2> 185965 INFO (qtp1327055148-1335) [n:127.0.0.1:51728_solr ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 186062 INFO (zkCallback-225-thread-3-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/dv_coll/state.json] for collection [dv_coll] has occurred - updating... (live nodes size: [2])
[junit4] 2> 186062 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/dv_coll/state.json] for collection [dv_coll] has occurred - updating... (live nodes size: [2])
[junit4] 2> 186376 INFO (OverseerCollectionConfigSetProcessor-97077659441954822-127.0.0.1:51728_solr-n_0000000000) [n:127.0.0.1:51728_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 186974 INFO (qtp1327055148-1335) [n:127.0.0.1:51728_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf1&maxShardsPerNode=2&name=dv_coll&action=CREATE&numShards=4&wt=javabin&version=2} status=0 QTime=2616
[junit4] 2> 187021 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.SchemaManager managed schema loaded . version : 0
[junit4] 2> 187029 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.IndexSchema [dv_coll_shard3_replica1] Schema name=minimal
[junit4] 2> 187045 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 187109 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.s.ZkIndexSchemaReader A schema change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/configs/conf1/managed-schema, has occurred - updating schema from ZooKeeper ...
[junit4] 2> 187109 INFO (zkCallback-225-thread-1-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.s.ZkIndexSchemaReader A schema change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/configs/conf1/managed-schema, has occurred - updating schema from ZooKeeper ...
[junit4] 2> 187109 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.ZkController Persisted config data to node /configs/conf1/managed-schema
[junit4] 2> 187109 INFO (zkCallback-225-thread-3-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.s.ZkIndexSchemaReader A schema change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/configs/conf1/managed-schema, has occurred - updating schema from ZooKeeper ...
[junit4] 2> 187109 INFO (zkCallback-224-thread-2-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.s.ZkIndexSchemaReader A schema change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/configs/conf1/managed-schema, has occurred - updating schema from ZooKeeper ...
[junit4] 2> 187110 INFO (zkCallback-225-thread-1-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.s.ZkIndexSchemaReader Retrieved schema version 1 from ZooKeeper
[junit4] 2> 187110 INFO (zkCallback-225-thread-3-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.s.ZkIndexSchemaReader Retrieved schema version 1 from ZooKeeper
[junit4] 2> 187110 INFO (zkCallback-224-thread-2-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.s.ZkIndexSchemaReader Retrieved schema version 1 from ZooKeeper
[junit4] 2> 187127 INFO (Thread-306) [n:127.0.0.1:51728_solr ] o.a.s.c.SolrCore config update listener called for core dv_coll_shard2_replica1
[junit4] 2> 187128 INFO (zkCallback-224-thread-2-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.s.IndexSchema [dv_coll_shard1_replica1] Schema name=minimal
[junit4] 2> 187128 INFO (zkCallback-225-thread-3-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.s.IndexSchema [dv_coll_shard2_replica1] Schema name=minimal
[junit4] 2> 187130 INFO (Thread-307) [n:127.0.0.1:51729_solr ] o.a.s.c.SolrCore config update listener called for core dv_coll_shard1_replica1
[junit4] 2> 187131 INFO (zkCallback-225-thread-1-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.s.IndexSchema [dv_coll_shard4_replica1] Schema name=minimal
[junit4] 2> 187178 INFO (zkCallback-225-thread-3-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 187179 INFO (zkCallback-225-thread-3-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.s.ZkIndexSchemaReader Finished refreshing schema in 69 ms
[junit4] 2> 187181 INFO (zkCallback-224-thread-2-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 187183 INFO (zkCallback-224-thread-2-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.s.ZkIndexSchemaReader Finished refreshing schema in 73 ms
[junit4] 2> 187189 INFO (zkCallback-225-thread-1-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 187190 INFO (Thread-307) [n:127.0.0.1:51729_solr ] o.a.s.c.SolrCore core reload dv_coll_shard1_replica1
[junit4] 2> 187190 INFO (Thread-306) [n:127.0.0.1:51728_solr ] o.a.s.c.SolrCore core reload dv_coll_shard2_replica1
[junit4] 2> 187195 INFO (zkCallback-225-thread-1-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.s.ZkIndexSchemaReader Finished refreshing schema in 85 ms
[junit4] 2> 187602 INFO (Thread-306) [n:127.0.0.1:51728_solr ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 187613 INFO (Thread-307) [n:127.0.0.1:51729_solr ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 187793 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 187815 INFO (Thread-306) [n:127.0.0.1:51728_solr ] o.a.s.s.IndexSchema [dv_coll_shard2_replica1] Schema name=minimal
[junit4] 2> 187849 INFO (Thread-307) [n:127.0.0.1:51729_solr ] o.a.s.s.IndexSchema [dv_coll_shard1_replica1] Schema name=minimal
[junit4] 2> 187850 INFO (Thread-306) [n:127.0.0.1:51728_solr ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 187872 INFO (Thread-306) [n:127.0.0.1:51728_solr ] o.a.s.c.CoreContainer Reloading SolrCore 'dv_coll_shard2_replica1' using configuration from collection dv_coll
[junit4] 2> 187880 INFO (Thread-307) [n:127.0.0.1:51729_solr ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 187881 INFO (Thread-307) [n:127.0.0.1:51729_solr ] o.a.s.c.CoreContainer Reloading SolrCore 'dv_coll_shard1_replica1' using configuration from collection dv_coll
[junit4] 2> 187897 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.IndexSchema [dv_coll_shard3_replica1] Schema name=minimal
[junit4] 2> 187897 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SolrCore [[dv_coll_shard2_replica1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node1/dv_coll_shard2_replica1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node1/./dv_coll_shard2_replica1/data/]
[junit4] 2> 187922 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [[dv_coll_shard1_replica1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/dv_coll_shard1_replica1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/./dv_coll_shard1_replica1/data/]
[junit4] 2> 187924 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 187925 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.CoreContainer Reloading SolrCore 'dv_coll_shard3_replica1' using configuration from collection dv_coll
[junit4] 2> 187958 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 187959 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 187961 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@583f7441[dv_coll_shard2_replica1] main]
[junit4] 2> 187963 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 187963 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 187963 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 187964 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6adb148e[dv_coll_shard1_replica1] main]
[junit4] 2> 187965 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 187965 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema
[junit4] 2> 187966 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 187967 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 1 is already the latest
[junit4] 2> 187967 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 187967 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SolrCore [[dv_coll_shard3_replica1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/dv_coll_shard3_replica1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/./dv_coll_shard3_replica1/data/]
[junit4] 2> 187969 INFO (searcherExecutor-882-thread-1-processing-n:127.0.0.1:51728_solr x:dv_coll_shard2_replica1 s:shard2 c:dv_coll r:core_node1) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SolrCore [dv_coll_shard2_replica1] Registered new searcher Searcher@583f7441[dv_coll_shard2_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 187969 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1553242555289698304
[junit4] 2> 187967 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 187970 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema
[junit4] 2> 187971 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 1 is already the latest
[junit4] 2> 187971 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 187971 INFO (searcherExecutor-883-thread-1-processing-n:127.0.0.1:51729_solr x:dv_coll_shard1_replica1 s:shard1 c:dv_coll r:core_node4) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [dv_coll_shard1_replica1] Registered new searcher Searcher@6adb148e[dv_coll_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 187981 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1553242555302281216
[junit4] 2> 188002 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 188002 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 188032 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@583a1c3a[dv_coll_shard3_replica1] main]
[junit4] 2> 188034 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 188035 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 188035 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema
[junit4] 2> 188036 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 1 is already the latest
[junit4] 2> 188037 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 188037 INFO (searcherExecutor-890-thread-1-processing-n:127.0.0.1:51729_solr x:dv_coll_shard3_replica1 s:shard3 c:dv_coll r:core_node3) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SolrCore [dv_coll_shard3_replica1] Registered new searcher Searcher@583a1c3a[dv_coll_shard3_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 188046 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1553242555370438656
[junit4] 2> 188047 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 188048 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@159daea6[dv_coll_shard2_replica1] main]
[junit4] 2> 188048 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SolrCore [dv_coll_shard2_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@18211c51
[junit4] 2> 188048 INFO (searcherExecutor-882-thread-1-processing-n:127.0.0.1:51728_solr x:dv_coll_shard2_replica1 s:shard2 c:dv_coll r:core_node1) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SolrCore [dv_coll_shard2_replica1] Registered new searcher Searcher@159daea6[dv_coll_shard2_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 188049 INFO (Thread-306) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SolrCore config update listener called for core dv_coll_shard4_replica1
[junit4] 2> 188050 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 188051 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@2d8943d0[dv_coll_shard1_replica1] main]
[junit4] 2> 188051 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [dv_coll_shard1_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@7132cfb9
[junit4] 2> 188051 INFO (searcherExecutor-883-thread-1-processing-n:127.0.0.1:51729_solr x:dv_coll_shard1_replica1 s:shard1 c:dv_coll r:core_node4) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [dv_coll_shard1_replica1] Registered new searcher Searcher@2d8943d0[dv_coll_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 188051 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore config update listener called for core dv_coll_shard3_replica1
[junit4] 2> 188054 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore core reload dv_coll_shard3_replica1
[junit4] 2> 188111 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 188111 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@3d0c24b9[dv_coll_shard3_replica1] main]
[junit4] 2> 188112 INFO (searcherExecutor-890-thread-1-processing-n:127.0.0.1:51729_solr x:dv_coll_shard3_replica1 s:shard3 c:dv_coll r:core_node3) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SolrCore [dv_coll_shard3_replica1] Registered new searcher Searcher@3d0c24b9[dv_coll_shard3_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 188115 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.ManagedIndexSchema Waiting up to 598 secs for 3 replicas to apply schema update version 1 for collection dv_coll
[junit4] 2> 188122 INFO (qtp1327055148-1341) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.S.Request [dv_coll_shard2_replica1] webapp=/solr path=/schema/zkversion params={refreshIfBelowVersion=1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 188122 INFO (qtp1327055148-1344) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.S.Request [dv_coll_shard4_replica1] webapp=/solr path=/schema/zkversion params={refreshIfBelowVersion=1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 188133 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.S.Request [dv_coll_shard1_replica1] webapp=/solr path=/schema/zkversion params={refreshIfBelowVersion=1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 188135 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 188137 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.ManagedIndexSchema Took 25.0ms for 3 replicas to apply schema update version 1 for collection dv_coll
[junit4] 2> 188138 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.s.ZkIndexSchemaReader Retrieved schema version 1 from ZooKeeper
[junit4] 2> 188138 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.S.Request [dv_coll_shard3_replica1] webapp=/solr path=/schema params={wt=javabin&version=2} status=0 QTime=1126
[junit4] 2> 188138 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SolrCore [dv_coll_shard3_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@1708447b
[junit4] 2> 188171 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.s.IndexSchema [dv_coll_shard3_replica1] Schema name=minimal
[junit4] 2> 188193 INFO (TEST-DocValuesNotIndexedTest.testGroupingDVOnly-seed#[54DB92C93207C57F]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testGroupingDVOnly
[junit4] 2> 188193 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 188194 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.s.ZkIndexSchemaReader Finished refreshing schema in 55 ms
[junit4] 2> 188194 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.IndexSchema [dv_coll_shard3_replica1] Schema name=minimal
[junit4] 2> 188221 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard3_replica1] webapp=/solr path=/update params={update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/&wt=javabin&version=2}{deleteByQuery=*:* (-1553242555546599424)} 0 6
[junit4] 2> 188350 INFO (qtp1822633701-1343) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard1_replica1] webapp=/solr path=/update params={update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/&wt=javabin&version=2}{deleteByQuery=*:* (-1553242555548696576)} 0 135
[junit4] 2> 188350 INFO (qtp1327055148-1344) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard4_replica1] webapp=/solr path=/update params={update.distrib=TOLEADER&distrib.from=http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/&wt=javabin&version=2}{deleteByQuery=*:* (-1553242555546599424)} 0 136
[junit4] 2> 188351 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard2_replica1] webapp=/solr path=/update params={wt=javabin&version=2}{deleteByQuery=*:* (-1553242555544502272)} 0 157
[junit4] 2> 188353 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 188359 INFO (qtp1327055148-1331) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 188359 INFO (qtp1822633701-1346) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 188359 INFO (qtp1327055148-1331) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 188359 INFO (qtp1822633701-1346) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 188359 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 188359 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 188360 INFO (qtp1327055148-1335) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 188361 INFO (qtp1327055148-1335) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 188371 INFO (qtp1327055148-1331) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@17ada05c[dv_coll_shard4_replica1] main]
[junit4] 2> 188372 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.CoreContainer Reloading SolrCore 'dv_coll_shard3_replica1' using configuration from collection dv_coll
[junit4] 2> 188372 INFO (searcherExecutor-864-thread-1-processing-n:127.0.0.1:51728_solr x:dv_coll_shard4_replica1 s:shard4 c:dv_coll r:core_node2) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.SolrCore [dv_coll_shard4_replica1] Registered new searcher Searcher@17ada05c[dv_coll_shard4_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 188383 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 188383 INFO (qtp1822633701-1346) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 188383 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard1_replica1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 24
[junit4] 2> 188383 INFO (qtp1822633701-1346) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard3_replica1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 24
[junit4] 2> 188384 INFO (qtp1327055148-1331) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 188384 INFO (qtp1327055148-1331) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard4_replica1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 25
[junit4] 2> 188384 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [[dv_coll_shard3_replica1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/dv_coll_shard3_replica1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001/tempDir-001/node2/./dv_coll_shard3_replica1/data/]
[junit4] 2> 188385 INFO (qtp1327055148-1335) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 188385 INFO (qtp1327055148-1335) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard2_replica1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 25
[junit4] 2> 188417 INFO (qtp1327055148-1341) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard2_replica1] webapp=/solr path=/update params={_stateVer_=dv_coll:3&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 64
[junit4] 2> 188418 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 188418 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 188419 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@42a39a3a[dv_coll_shard3_replica1] main]
[junit4] 2> 188421 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 188422 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 188422 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/conf1/managed-schema
[junit4] 2> 188424 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.ZkIndexSchemaReader Current schema version 1 is already the latest
[junit4] 2> 188424 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 188424 INFO (searcherExecutor-895-thread-1-processing-n:127.0.0.1:51729_solr x:dv_coll_shard1_replica1 s:shard1 c:dv_coll r:core_node4) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [dv_coll_shard3_replica1] Registered new searcher Searcher@42a39a3a[dv_coll_shard3_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 188451 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 188480 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard1_replica1] webapp=/solr path=/update params={_stateVer_=dv_coll:3&wt=javabin&version=2}{add=[1 (1553242555794063360), 8 (1553242555823423488), 10 (1553242555823423489), 110 (1553242555824472064), 11 (1553242555824472065), 13 (1553242555824472066), 14 (1553242555824472067), 24 (1553242555824472068), 27 (1553242555824472069), 28 (1553242555824472070), ... (15 adds)]} 0 30
[junit4] 2> 188481 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard2_replica1] webapp=/solr path=/update params={_stateVer_=dv_coll:3&wt=javabin&version=2}{add=[0 (1553242555796160512), 100 (1553242555823423488), 4 (1553242555823423489), 12 (1553242555824472064), 15 (1553242555824472065), 16 (1553242555824472066), 20 (1553242555824472067), 22 (1553242555824472068), 125 (1553242555825520640), 34 (1553242555825520641), ... (18 adds)]} 0 29
[junit4] 2> 188486 INFO (qtp1327055148-1338) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard4_replica1] webapp=/solr path=/update params={_stateVer_=dv_coll:3&wt=javabin&version=2}{add=[5 (1553242555794063360), 17 (1553242555830763520), 19 (1553242555830763521), 21 (1553242555830763522), 23 (1553242555830763523), 25 (1553242555830763524), 29 (1553242555831812096), 33 (1553242555831812097), 37 (1553242555831812098), 45 (1553242555831812099), ... (11 adds)]} 0 36
[junit4] 2> 188492 INFO (qtp1822633701-1339) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard3_replica1] webapp=/solr path=/update params={_stateVer_=dv_coll:3&wt=javabin&version=2}{add=[2 (1553242555796160512), 3 (1553242555823423488), 105 (1553242555834957824), 6 (1553242555836006400), 7 (1553242555837054976), 9 (1553242555837054977), 115 (1553242555837054978), 18 (1553242555837054979), 120 (1553242555837054980), 26 (1553242555837054981), ... (15 adds)]} 0 40
[junit4] 2> 188526 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 188526 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@324c9022
[junit4] 2> 188526 INFO (qtp1327055148-1331) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 188526 INFO (qtp1327055148-1331) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@663e0ae5
[junit4] 2> 188526 INFO (qtp1822633701-1343) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 188526 INFO (qtp1822633701-1343) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@316662d5
[junit4] 2> 188526 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 188526 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@71a92837
[junit4] 2> 188784 INFO (qtp1327055148-1331) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@76f59b5f[dv_coll_shard4_replica1] main]
[junit4] 2> 188795 INFO (qtp1327055148-1331) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 188795 INFO (searcherExecutor-864-thread-1-processing-n:127.0.0.1:51728_solr x:dv_coll_shard4_replica1 s:shard4 c:dv_coll r:core_node2) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.SolrCore [dv_coll_shard4_replica1] Registered new searcher Searcher@76f59b5f[dv_coll_shard4_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C11)))}
[junit4] 2> 188795 INFO (qtp1327055148-1331) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard4_replica1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:51729/solr/dv_coll_shard3_replica1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 269
[junit4] 2> 188806 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@3cfef15e[dv_coll_shard2_replica1] main]
[junit4] 2> 188817 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 188817 INFO (searcherExecutor-882-thread-1-processing-n:127.0.0.1:51728_solr x:dv_coll_shard2_replica1 s:shard2 c:dv_coll r:core_node1) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SolrCore [dv_coll_shard2_replica1] Registered new searcher Searcher@3cfef15e[dv_coll_shard2_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C18)))}
[junit4] 2> 188817 INFO (qtp1327055148-1340) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard2_replica1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:51729/solr/dv_coll_shard3_replica1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 291
[junit4] 2> 188817 INFO (Thread-307) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5df41ec8[dv_coll_shard3_replica1] main]
[junit4] 2> 188818 INFO (searcherExecutor-895-thread-1-processing-n:127.0.0.1:51729_solr x:dv_coll_shard1_replica1 s:shard1 c:dv_coll r:core_node4) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [dv_coll_shard3_replica1] Registered new searcher Searcher@5df41ec8[dv_coll_shard3_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C1)))}
[junit4] 2> 188819 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@22a9cab3[dv_coll_shard1_replica1] main]
[junit4] 2> 188820 INFO (searcherExecutor-883-thread-1-processing-n:127.0.0.1:51729_solr x:dv_coll_shard1_replica1 s:shard1 c:dv_coll r:core_node4) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [dv_coll_shard1_replica1] Registered new searcher Searcher@22a9cab3[dv_coll_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C15)))}
[junit4] 2> 188820 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 188820 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard1_replica1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:51729/solr/dv_coll_shard3_replica1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 294
[junit4] 2> 189418 INFO (qtp1822633701-1343) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@232701d5[dv_coll_shard3_replica1] main]
[junit4] 2> 189419 INFO (searcherExecutor-890-thread-1-processing-n:127.0.0.1:51729_solr x:dv_coll_shard3_replica1 s:shard3 c:dv_coll r:core_node3) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SolrCore [dv_coll_shard3_replica1] Registered new searcher Searcher@232701d5[dv_coll_shard3_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C1) Uninverting(_1(7.0.0):C14)))}
[junit4] 2> 189420 INFO (qtp1822633701-1343) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 189420 INFO (qtp1822633701-1343) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard3_replica1] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:51729/solr/dv_coll_shard3_replica1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 894
[junit4] 2> 189421 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.u.p.LogUpdateProcessorFactory [dv_coll_shard3_replica1] webapp=/solr path=/update params={_stateVer_=dv_coll:3&commit=true&wt=javabin&version=2}{commit=} 0 919
[junit4] 2> 189422 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SolrCore [dv_coll_shard3_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@412ae296
[junit4] 2> 189499 INFO (qtp1822633701-1342) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.S.Request [dv_coll_shard3_replica1] webapp=/solr path=/select params={df=text&group.distributed.first=true&distrib=false&_stateVer_=dv_coll:3&group.limit=100&fl=id,score&shards.purpose=2048&start=0&shard.url=http://127.0.0.1:51729/solr/dv_coll_shard3_replica1/&rows=100&version=2&q=*:*&NOW=1481287533584&isShard=true&wt=javabin&group.field=intGSF&group=true} status=0 QTime=60
[junit4] 2> 189499 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.S.Request [dv_coll_shard1_replica1] webapp=/solr path=/select params={df=text&group.distributed.first=true&distrib=false&_stateVer_=dv_coll:3&group.limit=100&fl=id,score&shards.purpose=2048&start=0&shard.url=http://127.0.0.1:51729/solr/dv_coll_shard1_replica1/&rows=100&version=2&q=*:*&NOW=1481287533584&isShard=true&wt=javabin&group.field=intGSF&group=true} status=0 QTime=64
[junit4] 2> 189500 INFO (qtp1327055148-1344) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.S.Request [dv_coll_shard2_replica1] webapp=/solr path=/select params={df=text&group.distributed.first=true&distrib=false&_stateVer_=dv_coll:3&group.limit=100&fl=id,score&shards.purpose=2048&start=0&shard.url=http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/&rows=100&version=2&q=*:*&NOW=1481287533584&isShard=true&wt=javabin&group.field=intGSF&group=true} status=0 QTime=64
[junit4] 2> 189500 INFO (qtp1327055148-1335) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.S.Request [dv_coll_shard4_replica1] webapp=/solr path=/select params={df=text&group.distributed.first=true&distrib=false&_stateVer_=dv_coll:3&group.limit=100&fl=id,score&shards.purpose=2048&start=0&shard.url=http://127.0.0.1:51728/solr/dv_coll_shard4_replica1/&rows=100&version=2&q=*:*&NOW=1481287533584&isShard=true&wt=javabin&group.field=intGSF&group=true} status=0 QTime=64
[junit4] 2> 189547 INFO (qtp1822633701-1339) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.S.Request [dv_coll_shard3_replica1] webapp=/solr path=/select params={df=text&distrib=false&_stateVer_=dv_coll:3&group.limit=100&fl=id,score&shards.purpose=4&start=0&shard.url=http://127.0.0.1:51729/solr/dv_coll_shard3_replica1/&rows=100&version=2&group.distributed.second=true&q=*:*&NOW=1481287533584&group.topgroups.intGSF=1146822199&group.topgroups.intGSF=%01&group.topgroups.intGSF=1146822307&group.topgroups.intGSF=1146822412&group.topgroups.intGSF=1146822512&group.topgroups.intGSF=1146822616&group.topgroups.intGSF=1146822722&group.topgroups.intGSF=1146822824&isShard=true&wt=javabin&group.field=intGSF&group=true} status=0 QTime=25
[junit4] 2> 189548 INFO (qtp1327055148-1337) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.S.Request [dv_coll_shard2_replica1] webapp=/solr path=/select params={df=text&distrib=false&_stateVer_=dv_coll:3&group.limit=100&fl=id,score&shards.purpose=4&start=0&shard.url=http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/&rows=100&version=2&group.distributed.second=true&q=*:*&NOW=1481287533584&group.topgroups.intGSF=1146822199&group.topgroups.intGSF=%01&group.topgroups.intGSF=1146822307&group.topgroups.intGSF=1146822412&group.topgroups.intGSF=1146822512&group.topgroups.intGSF=1146822616&group.topgroups.intGSF=1146822722&group.topgroups.intGSF=1146822824&isShard=true&wt=javabin&group.field=intGSF&group=true} status=0 QTime=27
[junit4] 2> 189548 INFO (qtp1822633701-1345) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.S.Request [dv_coll_shard1_replica1] webapp=/solr path=/select params={df=text&distrib=false&_stateVer_=dv_coll:3&group.limit=100&fl=id,score&shards.purpose=4&start=0&shard.url=http://127.0.0.1:51729/solr/dv_coll_shard1_replica1/&rows=100&version=2&group.distributed.second=true&q=*:*&NOW=1481287533584&group.topgroups.intGSF=1146822199&group.topgroups.intGSF=%01&group.topgroups.intGSF=1146822307&group.topgroups.intGSF=1146822412&group.topgroups.intGSF=1146822512&group.topgroups.intGSF=1146822616&group.topgroups.intGSF=1146822722&group.topgroups.intGSF=1146822824&isShard=true&wt=javabin&group.field=intGSF&group=true} status=0 QTime=25
[junit4] 2> 189549 INFO (qtp1327055148-1338) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.S.Request [dv_coll_shard4_replica1] webapp=/solr path=/select params={df=text&distrib=false&_stateVer_=dv_coll:3&group.limit=100&fl=id,score&shards.purpose=4&st
[...truncated too long message...]
oups.boolGSF=false&shard.url=http://127.0.0.1:51729/solr/dv_coll_shard1_replica1/&rows=10&version=2&group.distributed.second=true&q=*:*&NOW=1481287535843&isShard=true&wt=javabin&group.field=boolGSF&group=true} status=0 QTime=0
[junit4] 2> 191690 INFO (qtp1327055148-1341) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.S.Request [dv_coll_shard2_replica1] webapp=/solr path=/select params={q=*:*&df=text&distrib=false&_stateVer_=dv_coll:3&shards.purpose=64&NOW=1481287535843&ids=4&isShard=true&shard.url=http://127.0.0.1:51728/solr/dv_coll_shard2_replica1/&wt=javabin&version=2&group.field=boolGSF} status=0 QTime=0
[junit4] 2> 191690 INFO (qtp1822633701-1336) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.S.Request [dv_coll_shard3_replica1] webapp=/solr path=/select params={q=*:*&df=text&distrib=false&_stateVer_=dv_coll:3&shards.purpose=64&NOW=1481287535843&ids=2&isShard=true&shard.url=http://127.0.0.1:51729/solr/dv_coll_shard3_replica1/&wt=javabin&version=2&group.field=boolGSF} status=0 QTime=0
[junit4] 2> 191690 INFO (qtp1822633701-1332) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.S.Request [dv_coll_shard1_replica1] webapp=/solr path=/select params={q=*:*&df=text&distrib=false&_stateVer_=dv_coll:3&shards.purpose=64&NOW=1481287535843&ids=1&isShard=true&shard.url=http://127.0.0.1:51729/solr/dv_coll_shard1_replica1/&wt=javabin&version=2&group.field=boolGSF} status=0 QTime=0
[junit4] 2> 191691 INFO (qtp1822633701-1339) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.S.Request [dv_coll_shard1_replica1] webapp=/solr path=/select params={q=*:*&_stateVer_=dv_coll:3&wt=javabin&version=2&group.field=boolGSF&group=true} status=0 QTime=7
[junit4] 2> 191691 INFO (TEST-DocValuesNotIndexedTest.testGroupingDocAbsent-seed#[54DB92C93207C57F]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testGroupingDocAbsent
[junit4] 2> 191695 INFO (jetty-launcher-214-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@7d64b42f{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 191695 INFO (jetty-launcher-214-thread-2) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@137af0fc{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 191695 INFO (jetty-launcher-214-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=331570460
[junit4] 2> 191696 INFO (jetty-launcher-214-thread-2) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1433656419
[junit4] 2> 191699 INFO (coreCloseExecutor-900-thread-1) [n:127.0.0.1:51728_solr c:dv_coll s:shard2 r:core_node1 x:dv_coll_shard2_replica1] o.a.s.c.SolrCore [dv_coll_shard2_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@18d7b534
[junit4] 2> 191699 INFO (coreCloseExecutor-899-thread-1) [n:127.0.0.1:51729_solr c:dv_coll s:shard1 r:core_node4 x:dv_coll_shard1_replica1] o.a.s.c.SolrCore [dv_coll_shard1_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@2e99503a
[junit4] 2> 191701 INFO (coreCloseExecutor-899-thread-2) [n:127.0.0.1:51729_solr c:dv_coll s:shard3 r:core_node3 x:dv_coll_shard3_replica1] o.a.s.c.SolrCore [dv_coll_shard3_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@7468bd9c
[junit4] 2> 191701 INFO (coreCloseExecutor-900-thread-2) [n:127.0.0.1:51728_solr c:dv_coll s:shard4 r:core_node2 x:dv_coll_shard4_replica1] o.a.s.c.SolrCore [dv_coll_shard4_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@60aab00c
[junit4] 2> 191719 INFO (zkCallback-225-thread-3-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/dv_coll/state.json] for collection [dv_coll] has occurred - updating... (live nodes size: [2])
[junit4] 2> 191719 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/dv_coll/state.json] for collection [dv_coll] has occurred - updating... (live nodes size: [2])
[junit4] 2> 191751 INFO (jetty-launcher-214-thread-2) [ ] o.a.s.c.Overseer Overseer (id=97077659441954822-127.0.0.1:51728_solr-n_0000000000) closing
[junit4] 2> 191752 INFO (OverseerStateUpdate-97077659441954822-127.0.0.1:51728_solr-n_0000000000) [n:127.0.0.1:51728_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:51728_solr
[junit4] 2> 191763 WARN (zkCallback-225-thread-3-processing-n:127.0.0.1:51728_solr) [n:127.0.0.1:51728_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 191766 INFO (zkCallback-224-thread-2-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 191766 INFO (jetty-launcher-214-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@6cf1565{/solr,null,UNAVAILABLE}
[junit4] 2> 191767 INFO (zkCallback-224-thread-1-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:51729_solr
[junit4] 2> 191767 WARN (zkCallback-224-thread-2-processing-n:127.0.0.1:51729_solr) [n:127.0.0.1:51729_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 193268 INFO (jetty-launcher-214-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@f63ab84{/solr,null,UNAVAILABLE}
[junit4] 2> 193270 INFO (SUITE-DocValuesNotIndexedTest-seed#[54DB92C93207C57F]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:51726 51726
[junit4] 2> 194420 INFO (Thread-287) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:51726 51726
[junit4] 2> 195882 WARN (Thread-287) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 8 /solr/configs/conf1/managed-schema
[junit4] 2> 4 /solr/configs/conf1
[junit4] 2> 3 /solr/aliases.json
[junit4] 2> 3 /solr/clusterprops.json
[junit4] 2> 2 /solr/security.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/clusterstate.json
[junit4] 2> 2 /solr/configs/conf1/managed-schema
[junit4] 2> 2 /solr/collections/dv_coll/state.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 9 /solr/overseer/queue
[junit4] 2> 7 /solr/overseer/collection-queue-work
[junit4] 2> 3 /solr/live_nodes
[junit4] 2> 3 /solr/collections
[junit4] 2> 3 /solr/overseer/queue-work
[junit4] 2>
[junit4] 2> 195883 INFO (SUITE-DocValuesNotIndexedTest-seed#[54DB92C93207C57F]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DocValuesNotIndexedTest_54DB92C93207C57F-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {_version_=PostingsFormat(name=Memory), id=BlockTreeOrds(blocksize=128)}, docValues:{floatField=DocValuesFormat(name=Lucene70), doubleField=DocValuesFormat(name=Lucene70), intFieldMulti=DocValuesFormat(name=Direct), boolFieldMulti=DocValuesFormat(name=Lucene70), longFieldMulti=DocValuesFormat(name=Memory), floatGSL=DocValuesFormat(name=Lucene70), intField=DocValuesFormat(name=Memory), boolField=DocValuesFormat(name=Lucene70), stringFieldMulti=DocValuesFormat(name=Lucene70), dateFieldMulti=DocValuesFormat(name=Lucene70), longGSF=DocValuesFormat(name=Direct), doubleFieldMulti=DocValuesFormat(name=Lucene70), stringGSL=DocValuesFormat(name=Memory), doubleGSF=DocValuesFormat(name=Lucene70), doubleGSL=DocValuesFormat(name=Memory), stringGSF=DocValuesFormat(name=Lucene70), intGSL=DocValuesFormat(name=Lucene70), longField=DocValuesFormat(name=Direct), dateField=DocValuesFormat(name=Direct), dateGSF=DocValuesFormat(name=Lucene70), boolGSF=DocValuesFormat(name=Lucene70), longGSL=DocValuesFormat(name=Lucene70), boolGSL=DocValuesFormat(name=Direct), floatFieldMulti=DocValuesFormat(name=Memory), floatGSF=DocValuesFormat(name=Direct), dateGSL=DocValuesFormat(name=Direct), intGSF=DocValuesFormat(name=Memory), stringField=DocValuesFormat(name=Lucene70)}, maxPointsInLeafNode=35, maxMBSortInHeap=7.0557638158490725, sim=RandomSimilarity(queryNorm=true): {}, locale=es-MX, timezone=Pacific/Guadalcanal
[junit4] 2> NOTE: Mac OS X 10.11.6 x86_64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=3,threads=1,free=112984904,total=197459968
[junit4] 2> NOTE: All tests run in this JVM: [TestFieldResource, TestShortCircuitedRequests, DOMUtilTest, DistributedDebugComponentTest, OverseerRolesTest, AnalysisErrorHandlingTest, HttpSolrCallGetCoreTest, TestCollationField, TestBinaryResponseWriter, PrimitiveFieldTypeTest, TestJettySolrRunner, TestXmlQParser, TriLevelCompositeIdRoutingTest, DirectSolrSpellCheckerTest, TimerUtilsTest, TestMergePolicyConfig, StandardRequestHandlerTest, AssignTest, DistributedFacetExistsSmallTest, DocExpirationUpdateProcessorFactoryTest, ExitableDirectoryReaderTest, TestMacroExpander, TestLockTree, ZkNodePropsTest, SolrIndexConfigTest, SolrCoreTest, SystemInfoHandlerTest, TestSortByMinMaxFunction, MoreLikeThisHandlerTest, DocumentAnalysisRequestHandlerTest, HardAutoCommitTest, CollectionStateFormat2Test, SimpleFacetsTest, DocValuesNotIndexedTest]
[junit4] Completed [57/659 (1!)] on J0 in 11.97s, 4 tests, 1 failure <<< FAILURES!
[...truncated 64344 lines...]
[JENKINS] Lucene-Solr-master-MacOSX (64bit/jdk1.8.0) - Build # 3699
- Still Unstable!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-master-MacOSX/3699/
Java: 64bit/jdk1.8.0 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
FAILED: org.apache.solr.handler.TestReplicationHandler.doTestIndexAndConfigAliasReplication
Error Message:
expected:<1> but was:<0>
Stack Trace:
java.lang.AssertionError: expected:<1> but was:<0>
at __randomizedtesting.SeedInfo.seed([A79BEAB82FF795F5:50E804E0E91F3A13]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.failNotEquals(Assert.java:647)
at org.junit.Assert.assertEquals(Assert.java:128)
at org.junit.Assert.assertEquals(Assert.java:472)
at org.junit.Assert.assertEquals(Assert.java:456)
at org.apache.solr.handler.TestReplicationHandler.doTestIndexAndConfigAliasReplication(TestReplicationHandler.java:1329)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
at 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:367)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:811)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:462)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 11667 lines...]
[junit4] Suite: org.apache.solr.handler.TestReplicationHandler
[junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/init-core-data-001
[junit4] 2> 1604567 INFO (SUITE-TestReplicationHandler-seed#[A79BEAB82FF795F5]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl=None) w/ MAC_OS_X supressed clientAuth
[junit4] 2> 1604569 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testEmptyCommits
[junit4] 2> 1604569 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-001/collection1
[junit4] 2> 1604615 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1604616 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@4e92d6d9{/solr,null,AVAILABLE}
[junit4] 2> 1604619 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@29a60309{HTTP/1.1,[http/1.1]}{127.0.0.1:54391}
[junit4] 2> 1604619 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.Server Started @1610175ms
[junit4] 2> 1604619 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-001/collection1/data, hostContext=/solr, hostPort=54391}
[junit4] 2> 1604619 ERROR (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1604620 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.0.0
[junit4] 2> 1604620 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 1604620 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1604620 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-09T18:42:36.214Z
[junit4] 2> 1604620 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-001/solr.xml
[junit4] 2> 1604638 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-001/.
[junit4] 2> 1604638 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1604651 WARN (coreLoadExecutor-6391-thread-1) [ ] o.a.s.c.Config Beginning with Solr 5.5, <mergePolicy> is deprecated, use <mergePolicyFactory> instead.
[junit4] 2> 1604651 INFO (coreLoadExecutor-6391-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 1604658 INFO (coreLoadExecutor-6391-thread-1) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1604665 INFO (coreLoadExecutor-6391-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
[junit4] 2> 1604669 INFO (coreLoadExecutor-6391-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-001/./collection1
[junit4] 2> 1604669 INFO (coreLoadExecutor-6391-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-001/collection1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-001/./collection1/data/]
[junit4] 2> 1604670 INFO (coreLoadExecutor-6391-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1639634601, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
[junit4] 2> 1604679 INFO (coreLoadExecutor-6391-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1604680 INFO (coreLoadExecutor-6391-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1604680 INFO (coreLoadExecutor-6391-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=38, maxMergeAtOnceExplicit=37, maxMergedSegmentMB=15.689453125, floorSegmentMB=1.54296875, forceMergeDeletesPctAllowed=5.03654005498988, segmentsPerTier=17.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1604680 INFO (coreLoadExecutor-6391-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@702caa6[collection1] main]
[junit4] 2> 1604680 INFO (coreLoadExecutor-6391-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-001/collection1/conf
[junit4] 2> 1604681 INFO (coreLoadExecutor-6391-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Replication enabled for following config files: schema.xml,xslt/dummy.xsl
[junit4] 2> 1604681 INFO (coreLoadExecutor-6391-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1604681 INFO (searcherExecutor-6392-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@702caa6[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1605141 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-002/collection1
[junit4] 2> 1605163 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1605165 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@1f7548dd{/solr,null,AVAILABLE}
[junit4] 2> 1605166 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@296a370f{HTTP/1.1,[http/1.1]}{127.0.0.1:54392}
[junit4] 2> 1605166 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.Server Started @1610722ms
[junit4] 2> 1605166 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-002/collection1/data, hostContext=/solr, hostPort=54392}
[junit4] 2> 1605167 ERROR (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1605167 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.0.0
[junit4] 2> 1605167 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 1605167 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1605167 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-09T18:42:36.761Z
[junit4] 2> 1605168 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-002/solr.xml
[junit4] 2> 1605229 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-002/.
[junit4] 2> 1605229 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1605237 WARN (coreLoadExecutor-6401-thread-1) [ ] o.a.s.c.Config Beginning with Solr 5.5, <mergePolicy> is deprecated, use <mergePolicyFactory> instead.
[junit4] 2> 1605237 INFO (coreLoadExecutor-6401-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 1605243 INFO (coreLoadExecutor-6401-thread-1) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1605244 INFO (coreLoadExecutor-6401-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
[junit4] 2> 1605245 INFO (coreLoadExecutor-6401-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-002/./collection1
[junit4] 2> 1605246 INFO (coreLoadExecutor-6401-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-002/collection1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-002/./collection1/data/]
[junit4] 2> 1605247 INFO (coreLoadExecutor-6401-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1639634601, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
[junit4] 2> 1605253 INFO (coreLoadExecutor-6401-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1605253 INFO (coreLoadExecutor-6401-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1605253 INFO (coreLoadExecutor-6401-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=38, maxMergeAtOnceExplicit=37, maxMergedSegmentMB=15.689453125, floorSegmentMB=1.54296875, forceMergeDeletesPctAllowed=5.03654005498988, segmentsPerTier=17.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1605254 INFO (coreLoadExecutor-6401-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@66ed93e4[collection1] main]
[junit4] 2> 1605254 INFO (coreLoadExecutor-6401-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-002/collection1/conf
[junit4] 2> 1605256 INFO (coreLoadExecutor-6401-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 1000ms
[junit4] 2> 1605256 INFO (searcherExecutor-6402-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@66ed93e4[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1605258 INFO (qtp28261027-13601) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1605258 INFO (indexFetcher-6406-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Master's generation: 1
[junit4] 2> 1605258 INFO (indexFetcher-6406-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Master's version: 0
[junit4] 2> 1605258 INFO (indexFetcher-6406-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 1605762 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=*:*&sort=id+desc&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 1605763 INFO (qtp28261027-13604) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[1]} 0 0
[junit4] 2> 1605772 INFO (qtp28261027-13605) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1605772 INFO (qtp28261027-13605) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@126f1b46
[junit4] 2> 1605775 INFO (qtp28261027-13605) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6fe8136f[collection1] main]
[junit4] 2> 1605775 INFO (qtp28261027-13605) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1605775 INFO (searcherExecutor-6392-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@6fe8136f[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C1)))}
[junit4] 2> 1605776 INFO (qtp28261027-13605) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={commit=true&wt=javabin&version=2}{commit=} 0 3
[junit4] 2> 1605779 WARN (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher 'masterUrl' must be specified without the /replication suffix
[junit4] 2> 1605780 INFO (qtp28261027-13606) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1605780 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Master's generation: 2
[junit4] 2> 1605780 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Master's version: 1481308957366
[junit4] 2> 1605780 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 1605780 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Starting replication process
[junit4] 2> 1605830 INFO (qtp28261027-13599) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&wt=javabin&version=2&command=filelist} status=0 QTime=49
[junit4] 2> 1605831 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Number of files in latest index in master: 10
[junit4] 2> 1605831 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=40, maxMergeAtOnceExplicit=20, maxMergedSegmentMB=89.7197265625, floorSegmentMB=0.375, forceMergeDeletesPctAllowed=20.398354721589598, segmentsPerTier=29.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 1605832 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1605832 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Starting download (fullCopy=false) to MockDirectoryWrapper(RAMDirectory@ea80a03 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@74fcef2a)
[junit4] 2> 1605833 INFO (qtp28261027-13601) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&file=_0.si&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605834 INFO (qtp28261027-13602) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&file=_0.nvd&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605835 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&file=_0.fdx&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605838 INFO (qtp28261027-13604) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&file=_0_Asserting_0.doc&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605841 INFO (qtp28261027-13605) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&file=_0_Asserting_0.tim&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605844 INFO (qtp28261027-13606) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&file=_0.fdt&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605845 INFO (qtp28261027-13599) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&file=_0_Asserting_0.tip&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605846 INFO (qtp28261027-13601) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&file=_0.fnm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605847 INFO (qtp28261027-13602) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&file=_0.nvm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605849 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=2&qt=/replication&file=segments_2&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605850 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Total time taken for download (fullCopy=false,bytesDownloaded=1669) : 0 secs (null bytes/sec) to MockDirectoryWrapper(RAMDirectory@ea80a03 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@74fcef2a)
[junit4] 2> 1605851 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=21, maxMergedSegmentMB=38.0458984375, floorSegmentMB=1.0302734375, forceMergeDeletesPctAllowed=22.513263973500866, segmentsPerTier=32.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1605853 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1605854 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@173bd67a[collection1] main]
[junit4] 2> 1605855 INFO (searcherExecutor-6402-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@173bd67a[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C1)))}
[junit4] 2> 1605855 INFO (qtp1824522089-13618) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={wait=true&masterUrl=http://127.0.0.1:54391/solr/collection1/replication&command=fetchindex} status=0 QTime=77
[junit4] 2> 1605862 INFO (qtp1824522089-13619) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=name:empty1&sort=id+desc&wt=javabin&version=2} hits=1 status=0 QTime=0
[junit4] 2> 1605862 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.h.TestReplicationHandler Waited for 0ms and found 1 docs
[junit4] 2> 1605870 INFO (qtp28261027-13604) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=7
[junit4] 2> 1605871 INFO (qtp28261027-13605) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=0
[junit4] 2> 1605873 INFO (qtp28261027-13606) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={slave=false&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=0
[junit4] 2> 1605873 INFO (qtp1824522089-13620) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=1
[junit4] 2> 1605874 INFO (qtp28261027-13599) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=assertVersions&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1605874 INFO (qtp1824522089-13621) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=assertVersions&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1605875 INFO (qtp28261027-13599) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1605875 INFO (qtp28261027-13599) [ x:collection1] o.a.s.u.DirectUpdateHandler2 No uncommitted changes. Skipping IW.commit.
[junit4] 2> 1605875 INFO (qtp28261027-13599) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1605875 INFO (qtp28261027-13599) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={commit=true&wt=javabin&version=2}{commit=} 0 0
[junit4] 2> 1605877 WARN (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher 'masterUrl' must be specified without the /replication suffix
[junit4] 2> 1605878 INFO (qtp28261027-13602) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1605879 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Master's generation: 2
[junit4] 2> 1605879 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Master's version: 1481308957366
[junit4] 2> 1605879 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Slave's generation: 2
[junit4] 2> 1605879 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Slave in sync with master.
[junit4] 2> 1605879 INFO (qtp1824522089-13622) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={wait=true&masterUrl=http://127.0.0.1:54391/solr/collection1/replication&command=fetchindex} status=0 QTime=2
[junit4] 2> 1605881 INFO (qtp28261027-13603) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[2]} 0 1
[junit4] 2> 1605882 INFO (qtp28261027-13604) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1605882 INFO (qtp28261027-13604) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@126f1b46
[junit4] 2> 1605884 INFO (qtp28261027-13604) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@20a9d20a[collection1] main]
[junit4] 2> 1605884 INFO (qtp28261027-13604) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1605884 INFO (searcherExecutor-6392-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@20a9d20a[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C1) Uninverting(_1(7.0.0):C1)))}
[junit4] 2> 1605884 INFO (qtp28261027-13604) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={commit=true&wt=javabin&version=2}{commit=} 0 2
[junit4] 2> 1605886 WARN (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher 'masterUrl' must be specified without the /replication suffix
[junit4] 2> 1605887 INFO (qtp28261027-13605) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1605887 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Master's generation: 3
[junit4] 2> 1605887 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Master's version: 1481308957476
[junit4] 2> 1605887 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Slave's generation: 2
[junit4] 2> 1605887 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Starting replication process
[junit4] 2> 1605888 INFO (qtp28261027-13606) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&wt=javabin&version=2&command=filelist} status=0 QTime=0
[junit4] 2> 1605888 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Number of files in latest index in master: 19
[junit4] 2> 1605889 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=40, maxMergeAtOnceExplicit=20, maxMergedSegmentMB=89.7197265625, floorSegmentMB=0.375, forceMergeDeletesPctAllowed=20.398354721589598, segmentsPerTier=29.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 1605890 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1605890 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Starting download (fullCopy=false) to MockDirectoryWrapper(RAMDirectory@4c687d9c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@5d566880)
[junit4] 2> 1605890 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.si because it already exists
[junit4] 2> 1605890 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.nvd because it already exists
[junit4] 2> 1605890 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.fdx because it already exists
[junit4] 2> 1605890 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0_Asserting_0.doc because it already exists
[junit4] 2> 1605890 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0_Asserting_0.tim because it already exists
[junit4] 2> 1605890 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.fdt because it already exists
[junit4] 2> 1605891 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0_Asserting_0.tip because it already exists
[junit4] 2> 1605891 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.fnm because it already exists
[junit4] 2> 1605891 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.nvm because it already exists
[junit4] 2> 1605891 INFO (qtp28261027-13601) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_1_Asserting_0.tip&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605892 INFO (qtp28261027-13599) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_1.si&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605893 INFO (qtp28261027-13602) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_1.nvd&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605894 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_1_Asserting_0.doc&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605895 INFO (qtp28261027-13604) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_1_Asserting_0.tim&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605896 INFO (qtp28261027-13605) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_1.fdx&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605897 INFO (qtp28261027-13606) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_1.fnm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605898 INFO (qtp28261027-13601) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_1.nvm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605899 INFO (qtp28261027-13599) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=_1.fdt&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605899 INFO (qtp28261027-13602) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=3&qt=/replication&file=segments_3&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1605900 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Total time taken for download (fullCopy=false,bytesDownloaded=1732) : 0 secs (null bytes/sec) to MockDirectoryWrapper(RAMDirectory@4c687d9c lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@5d566880)
[junit4] 2> 1605902 WARN (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Exception while updating statistics
[junit4] 2> java.io.IOException: file "replication.properties" was already written to
[junit4] 2> at org.apache.lucene.store.MockDirectoryWrapper.createOutput(MockDirectoryWrapper.java:654)
[junit4] 2> at org.apache.solr.handler.IndexFetcher.logReplicationTimeAndConfFiles(IndexFetcher.java:689)
[junit4] 2> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:501)
[junit4] 2> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:265)
[junit4] 2> at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:397)
[junit4] 2> at org.apache.solr.handler.ReplicationHandler.lambda$handleRequestBody$0(ReplicationHandler.java:279)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1605903 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=21, maxMergedSegmentMB=38.0458984375, floorSegmentMB=1.0302734375, forceMergeDeletesPctAllowed=22.513263973500866, segmentsPerTier=32.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1605938 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1605949 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@7cb25a4d[collection1] main]
[junit4] 2> 1605949 INFO (searcherExecutor-6402-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@7cb25a4d[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C1) Uninverting(_1(7.0.0):C1)))}
[junit4] 2> 1605950 INFO (qtp1824522089-13623) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={wait=true&masterUrl=http://127.0.0.1:54391/solr/collection1/replication&command=fetchindex} status=0 QTime=64
[junit4] 2> 1605951 INFO (qtp1824522089-13616) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=name:empty2&sort=id+desc&wt=javabin&version=2} hits=1 status=0 QTime=0
[junit4] 2> 1605952 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.h.TestReplicationHandler Waited for 0ms and found 1 docs
[junit4] 2> 1605952 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=0
[junit4] 2> 1605953 INFO (qtp28261027-13604) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=0
[junit4] 2> 1605954 INFO (qtp28261027-13605) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={slave=false&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=0
[junit4] 2> 1605954 INFO (qtp1824522089-13618) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=0
[junit4] 2> 1605955 INFO (qtp28261027-13606) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=assertVersions&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1605956 INFO (qtp1824522089-13619) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=assertVersions&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1605957 INFO (qtp28261027-13601) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[3]} 0 0
[junit4] 2> 1605957 INFO (qtp28261027-13599) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1605957 INFO (qtp28261027-13599) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@126f1b46
[junit4] 2> 1605959 INFO (qtp28261027-13599) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5f1b929b[collection1] realtime]
[junit4] 2> 1605960 INFO (qtp28261027-13599) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1605960 INFO (qtp28261027-13599) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={openSearcher=false&commit=true&wt=javabin&version=2}{commit=} 0 2
[junit4] 2> 1605961 WARN (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher 'masterUrl' must be specified without the /replication suffix
[junit4] 2> 1605963 INFO (qtp28261027-13602) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1605963 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Master's generation: 4
[junit4] 2> 1605963 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Master's version: 1481308957551
[junit4] 2> 1605963 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Slave's generation: 3
[junit4] 2> 1605963 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Starting replication process
[junit4] 2> 1605964 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&wt=javabin&version=2&command=filelist} status=0 QTime=0
[junit4] 2> 1605964 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Number of files in latest index in master: 28
[junit4] 2> 1605966 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=40, maxMergeAtOnceExplicit=20, maxMergedSegmentMB=89.7197265625, floorSegmentMB=0.375, forceMergeDeletesPctAllowed=20.398354721589598, segmentsPerTier=29.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 1605967 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1605967 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1605967 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1606971 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1606971 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1607981 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1607981 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1608987 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1608987 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1609992 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1609992 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1611002 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1611002 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1612007 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1612007 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1613018 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1613018 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1614024 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1614024 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1615024 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1615024 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1616035 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Found unused file: segments_2
[junit4] 2> 1616035 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Sleeping for 1000ms to wait for unused lucene index files to be delete-able
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher IndexFetcher slept for 11000ms for unused lucene index files to be delete-able
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Starting download (fullCopy=false) to MockDirectoryWrapper(RAMDirectory@497ca9b9 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@397d4a16)
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.si because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.nvd because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.fdx because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0_Asserting_0.doc because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0_Asserting_0.tim because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.fdt because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0_Asserting_0.tip because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.fnm because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.nvm because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1_Asserting_0.tip because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.si because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.nvd because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1_Asserting_0.doc because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1_Asserting_0.tim because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.fdx because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.fnm because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.nvm because it already exists
[junit4] 2> 1617036 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.fdt because it already exists
[junit4] 2> 1617039 INFO (qtp28261027-13604) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&file=_2.nvd&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617040 INFO (qtp28261027-13605) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&file=_2.si&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617042 INFO (qtp28261027-13606) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&file=_2.fdt&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617043 INFO (qtp28261027-13601) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&file=_2_Asserting_0.tip&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617044 INFO (qtp28261027-13599) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&file=_2.fnm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617044 INFO (qtp28261027-13602) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&file=_2.nvm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617045 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&file=_2.fdx&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617046 INFO (qtp28261027-13604) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&file=_2_Asserting_0.doc&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617047 INFO (qtp28261027-13605) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&file=_2_Asserting_0.tim&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617048 INFO (qtp28261027-13606) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=4&qt=/replication&file=segments_4&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617049 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Total time taken for download (fullCopy=false,bytesDownloaded=1795) : 11 secs (163 bytes/sec) to MockDirectoryWrapper(RAMDirectory@497ca9b9 lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@397d4a16)
[junit4] 2> 1617051 WARN (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Exception while updating statistics
[junit4] 2> java.io.IOException: file "replication.properties" was already written to
[junit4] 2> at org.apache.lucene.store.MockDirectoryWrapper.createOutput(MockDirectoryWrapper.java:654)
[junit4] 2> at org.apache.solr.handler.IndexFetcher.logReplicationTimeAndConfFiles(IndexFetcher.java:689)
[junit4] 2> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:501)
[junit4] 2> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:265)
[junit4] 2> at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:397)
[junit4] 2> at org.apache.solr.handler.ReplicationHandler.lambda$handleRequestBody$0(ReplicationHandler.java:279)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1617051 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=21, maxMergedSegmentMB=38.0458984375, floorSegmentMB=1.0302734375, forceMergeDeletesPctAllowed=22.513263973500866, segmentsPerTier=32.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1617052 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1617055 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@527629d4[collection1] main]
[junit4] 2> 1617055 INFO (searcherExecutor-6402-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@527629d4[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C1) Uninverting(_1(7.0.0):C1) Uninverting(_2(7.0.0):C1)))}
[junit4] 2> 1617055 INFO (qtp1824522089-13620) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={wait=true&masterUrl=http://127.0.0.1:54391/solr/collection1/replication&command=fetchindex} status=0 QTime=11094
[junit4] 2> 1617058 INFO (qtp28261027-13601) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=name:empty3&sort=id+desc&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 1617059 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.h.TestReplicationHandler Waited for 0ms and found 0 docs
[junit4] 2> 1617062 INFO (qtp1824522089-13621) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=name:empty3&sort=id+desc&wt=javabin&version=2} hits=1 status=0 QTime=0
[junit4] 2> 1617062 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.h.TestReplicationHandler Waited for 0ms and found 1 docs
[junit4] 2> 1617063 INFO (qtp28261027-13601) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[4]} 0 0
[junit4] 2> 1617063 INFO (qtp28261027-13602) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1617063 INFO (qtp28261027-13602) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@126f1b46
[junit4] 2> 1617065 INFO (qtp28261027-13602) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5d25de44[collection1] main]
[junit4] 2> 1617065 INFO (qtp28261027-13602) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1617065 INFO (searcherExecutor-6392-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@5d25de44[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C1) Uninverting(_1(7.0.0):C1) Uninverting(_2(7.0.0):C1) Uninverting(_3(7.0.0):C1)))}
[junit4] 2> 1617066 INFO (qtp28261027-13602) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/solr path=/update params={commit=true&wt=javabin&version=2}{commit=} 0 2
[junit4] 2> 1617070 WARN (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher 'masterUrl' must be specified without the /replication suffix
[junit4] 2> 1617071 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1617072 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Master's generation: 5
[junit4] 2> 1617072 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Master's version: 1481308968657
[junit4] 2> 1617072 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Slave's generation: 4
[junit4] 2> 1617072 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Starting replication process
[junit4] 2> 1617073 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&wt=javabin&version=2&command=filelist} status=0 QTime=0
[junit4] 2> 1617073 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Number of files in latest index in master: 37
[junit4] 2> 1617075 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=40, maxMergeAtOnceExplicit=20, maxMergedSegmentMB=89.7197265625, floorSegmentMB=0.375, forceMergeDeletesPctAllowed=20.398354721589598, segmentsPerTier=29.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0
[junit4] 2> 1617075 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Starting download (fullCopy=false) to MockDirectoryWrapper(RAMDirectory@1af475cc lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@14552039)
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.si because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.nvd because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.fdx because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0_Asserting_0.doc because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0_Asserting_0.tim because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.fdt because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0_Asserting_0.tip because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.fnm because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _0.nvm because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1_Asserting_0.tip because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.si because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.nvd because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1_Asserting_0.doc because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1_Asserting_0.tim because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.fdx because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.fnm because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.nvm because it already exists
[junit4] 2> 1617076 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _1.fdt because it already exists
[junit4] 2> 1617077 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _2.nvd because it already exists
[junit4] 2> 1617077 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _2.si because it already exists
[junit4] 2> 1617077 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _2.fdt because it already exists
[junit4] 2> 1617077 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _2_Asserting_0.tip because it already exists
[junit4] 2> 1617077 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _2.fnm because it already exists
[junit4] 2> 1617077 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _2.nvm because it already exists
[junit4] 2> 1617077 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _2.fdx because it already exists
[junit4] 2> 1617077 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _2_Asserting_0.doc because it already exists
[junit4] 2> 1617077 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Skipping download for _2_Asserting_0.tim because it already exists
[junit4] 2> 1617077 INFO (qtp28261027-13605) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&file=_3.fdx&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617079 INFO (qtp28261027-13606) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&file=_3.si&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617080 INFO (qtp28261027-13599) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&file=_3.nvd&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617081 INFO (qtp28261027-13601) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&file=_3_Asserting_0.doc&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617082 INFO (qtp28261027-13602) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&file=_3.fnm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617083 INFO (qtp28261027-13604) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&file=_3.nvm&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617084 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&file=_3_Asserting_0.tim&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617085 INFO (qtp28261027-13605) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&file=_3.fdt&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617086 INFO (qtp28261027-13606) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&file=_3_Asserting_0.tip&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617104 INFO (qtp28261027-13599) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={generation=5&qt=/replication&file=segments_5&checksum=true&wt=filestream&command=filecontent} status=0 QTime=0
[junit4] 2> 1617104 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Total time taken for download (fullCopy=false,bytesDownloaded=1858) : 0 secs (null bytes/sec) to MockDirectoryWrapper(RAMDirectory@1af475cc lockFactory=org.apache.lucene.store.SingleInstanceLockFactory@14552039)
[junit4] 2> 1617106 WARN (explicit-fetchindex-cmd) [ x:collection1] o.a.s.h.IndexFetcher Exception while updating statistics
[junit4] 2> java.io.IOException: file "replication.properties" was already written to
[junit4] 2> at org.apache.lucene.store.MockDirectoryWrapper.createOutput(MockDirectoryWrapper.java:654)
[junit4] 2> at org.apache.solr.handler.IndexFetcher.logReplicationTimeAndConfFiles(IndexFetcher.java:689)
[junit4] 2> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:501)
[junit4] 2> at org.apache.solr.handler.IndexFetcher.fetchLatestIndex(IndexFetcher.java:265)
[junit4] 2> at org.apache.solr.handler.ReplicationHandler.doFetch(ReplicationHandler.java:397)
[junit4] 2> at org.apache.solr.handler.ReplicationHandler.lambda$handleRequestBody$0(ReplicationHandler.java:279)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1617106 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=11, maxMergeAtOnceExplicit=21, maxMergedSegmentMB=38.0458984375, floorSegmentMB=1.0302734375, forceMergeDeletesPctAllowed=22.513263973500866, segmentsPerTier=32.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1617107 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 1617108 INFO (explicit-fetchindex-cmd) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1aea1c86[collection1] main]
[junit4] 2> 1617108 INFO (searcherExecutor-6402-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@1aea1c86[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C1) Uninverting(_1(7.0.0):C1) Uninverting(_2(7.0.0):C1) Uninverting(_3(7.0.0):C1)))}
[junit4] 2> 1617108 INFO (qtp1824522089-13621) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={wait=true&masterUrl=http://127.0.0.1:54391/solr/collection1/replication&command=fetchindex} status=0 QTime=38
[junit4] 2> 1617110 INFO (qtp28261027-13599) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=name:(empty1+empty2+empty3+empty4)&sort=id+desc&wt=javabin&version=2} hits=4 status=0 QTime=0
[junit4] 2> 1617111 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.h.TestReplicationHandler Waited for 0ms and found 4 docs
[junit4] 2> 1617112 INFO (qtp1824522089-13623) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=name:(empty1+empty2+empty3+empty4)&sort=id+desc&wt=javabin&version=2} hits=4 status=0 QTime=0
[junit4] 2> 1617113 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.h.TestReplicationHandler Waited for 0ms and found 4 docs
[junit4] 2> 1617121 INFO (qtp28261027-13602) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=5
[junit4] 2> 1617122 INFO (qtp28261027-13604) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=0
[junit4] 2> 1617124 INFO (qtp28261027-13603) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={slave=false&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=0
[junit4] 2> 1617124 INFO (qtp1824522089-13623) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=getDetails&qt=/replication&wt=javabin&version=2&command=details} status=0 QTime=1
[junit4] 2> 1617125 INFO (qtp28261027-13605) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=assertVersions&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1617126 INFO (qtp1824522089-13618) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={_trace=assertVersions&qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1617126 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testEmptyCommits
[junit4] 2> 1617127 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@29a60309{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1617127 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=217806580
[junit4] 2> 1617128 INFO (coreCloseExecutor-6411-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@581500a9
[junit4] 2> 1617130 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@4e92d6d9{/solr,null,UNAVAILABLE}
[junit4] 2> 1617139 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@296a370f{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1617139 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=536446861
[junit4] 2> 1617140 INFO (coreCloseExecutor-6413-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@63d43794
[junit4] 2> 1617147 INFO (TEST-TestReplicationHandler.testEmptyCommits-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@1f7548dd{/solr,null,UNAVAILABLE}
[junit4] 2> 1617153 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.SolrTestCaseJ4 ###Starting doTestIndexFetchWithMasterUrl
[junit4] 2> 1617153 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-003/collection1
[junit4] 2> 1617160 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1617161 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@3172091{/solr,null,AVAILABLE}
[junit4] 2> 1617161 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@52681c51{HTTP/1.1,[http/1.1]}{127.0.0.1:54417}
[junit4] 2> 1617161 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.Server Started @1622718ms
[junit4] 2> 1617161 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-003/collection1/data, hostContext=/solr, hostPort=54417}
[junit4] 2> 1617162 ERROR (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1617163 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.0.0
[junit4] 2> 1617163 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 1617163 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1617163 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-09T18:42:48.757Z
[junit4] 2> 1617163 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-003/solr.xml
[junit4] 2> 1617175 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-003/.
[junit4] 2> 1617175 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1617183 WARN (coreLoadExecutor-6420-thread-1) [ ] o.a.s.c.Config Beginning with Solr 5.5, <mergePolicy> is deprecated, use <mergePolicyFactory> instead.
[junit4] 2> 1617183 INFO (coreLoadExecutor-6420-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 1617193 INFO (coreLoadExecutor-6420-thread-1) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1617195 INFO (coreLoadExecutor-6420-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
[junit4] 2> 1617196 INFO (coreLoadExecutor-6420-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-003/./collection1
[junit4] 2> 1617196 INFO (coreLoadExecutor-6420-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-003/collection1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-003/./collection1/data/]
[junit4] 2> 1617202 INFO (coreLoadExecutor-6420-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1639634601, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
[junit4] 2> 1617216 INFO (coreLoadExecutor-6420-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1617216 INFO (coreLoadExecutor-6420-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1617217 INFO (coreLoadExecutor-6420-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=38, maxMergeAtOnceExplicit=37, maxMergedSegmentMB=15.689453125, floorSegmentMB=1.54296875, forceMergeDeletesPctAllowed=5.03654005498988, segmentsPerTier=17.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1617217 INFO (coreLoadExecutor-6420-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@4cae3379[collection1] main]
[junit4] 2> 1617218 INFO (coreLoadExecutor-6420-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-003/collection1/conf
[junit4] 2> 1617218 INFO (coreLoadExecutor-6420-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Replication enabled for following config files: schema.xml,xslt/dummy.xsl
[junit4] 2> 1617219 INFO (coreLoadExecutor-6420-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1617219 INFO (searcherExecutor-6421-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@4cae3379[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1617680 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-004/collection1
[junit4] 2> 1617703 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1617705 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@22b1229e{/solr,null,AVAILABLE}
[junit4] 2> 1617706 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@4f28a19d{HTTP/1.1,[http/1.1]}{127.0.0.1:54418}
[junit4] 2> 1617706 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.Server Started @1623262ms
[junit4] 2> 1617706 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {solr.data.dir=/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-004/collection1/data, hostContext=/solr, hostPort=54418}
[junit4] 2> 1617706 ERROR (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1617707 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.0.0
[junit4] 2> 1617707 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 1617707 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1617707 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2016-12-09T18:42:49.301Z
[junit4] 2> 1617708 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-004/solr.xml
[junit4] 2> 1617724 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-004/.
[junit4] 2> 1617724 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 1617742 WARN (coreLoadExecutor-6430-thread-1) [ ] o.a.s.c.Config Beginning with Solr 5.5, <mergePolicy> is deprecated, use <mergePolicyFactory> instead.
[junit4] 2> 1617743 INFO (coreLoadExecutor-6430-thread-1) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 1617749 INFO (coreLoadExecutor-6430-thread-1) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 1617754 INFO (coreLoadExecutor-6430-thread-1) [ ] o.a.s.s.IndexSchema Loaded schema test/1.2 with uniqueid field id
[junit4] 2> 1617761 INFO (coreLoadExecutor-6430-thread-1) [ ] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-004/./collection1
[junit4] 2> 1617761 INFO (coreLoadExecutor-6430-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-004/collection1], dataDir=[/Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-004/./collection1/data/]
[junit4] 2> 1617763 INFO (coreLoadExecutor-6430-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.AlcoholicMergePolicy: [AlcoholicMergePolicy: minMergeSize=0, mergeFactor=10, maxMergeSize=1639634601, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.1]
[junit4] 2> 1617776 INFO (coreLoadExecutor-6430-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1617776 INFO (coreLoadExecutor-6430-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1617776 INFO (coreLoadExecutor-6430-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=38, maxMergeAtOnceExplicit=37, maxMergedSegmentMB=15.689453125, floorSegmentMB=1.54296875, forceMergeDeletesPctAllowed=5.03654005498988, segmentsPerTier=17.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 1617777 INFO (coreLoadExecutor-6430-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@262b0b60[collection1] main]
[junit4] 2> 1617777 INFO (coreLoadExecutor-6430-thread-1) [ x:collection1] o.a.s.r.ManagedResourceStorage File-based storage initialized to use dir: /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001/solr-instance-004/collection1/conf
[junit4] 2> 1617778 INFO (coreLoadExecutor-6430-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Poll scheduled at an interval of 1000ms
[junit4] 2> 1617778 INFO (searcherExecutor-6431-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@262b0b60[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1618026 INFO (qtp549540140-13651) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1618026 INFO (indexFetcher-6435-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Master's generation: 1
[junit4] 2> 1618026 INFO (indexFetcher-6435-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Master's version: 0
[junit4] 2> 1618026 INFO (indexFetcher-6435-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Slave's generation: 1
[junit4] 2> 1618229 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@4f28a19d{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1618229 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1204828933
[junit4] 2> 1618230 INFO (coreCloseExecutor-6436-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@3d5f40a5
[junit4] 2> 1618232 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@22b1229e{/solr,null,UNAVAILABLE}
[junit4] 2> 1618234 INFO (TEST-TestReplicationHandler.doTestIndexFetchWithMasterUrl-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1618236 INFO (TEST-TestR
[...truncated too long message...]
] o.a.s.h.TestReplicationHandler Waiting for 1 docs
[junit4] 2> 1712746 INFO (qtp810554522-14627) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=id:2001&sort=id+desc&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 1712746 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.a.s.h.TestReplicationHandler Waiting for 1 docs
[junit4] 2> 1712855 INFO (qtp810554522-14631) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=id:2001&sort=id+desc&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 1712855 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.a.s.h.TestReplicationHandler Waiting for 1 docs
[junit4] 2> 1712951 INFO (qtp1241233943-14608) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4] 2> 1712951 INFO (indexFetcher-7036-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Master's generation: 2
[junit4] 2> 1712951 INFO (indexFetcher-7036-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Master's version: 1481309031724
[junit4] 2> 1712952 INFO (indexFetcher-7036-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Slave's generation: 2
[junit4] 2> 1712952 INFO (indexFetcher-7036-thread-1) [ x:collection1] o.a.s.h.IndexFetcher Slave in sync with master.
[junit4] 2> 1712966 INFO (qtp810554522-14632) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=id:2001&sort=id+desc&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 1712966 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.a.s.h.TestReplicationHandler Waiting for 1 docs
[junit4] 2> 1713076 INFO (qtp810554522-14633) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/solr path=/select params={q=id:2001&sort=id+desc&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 1713076 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.a.s.h.TestReplicationHandler Waited for 30000ms and found 0 docs
[junit4] 2> 1713077 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.a.s.SolrTestCaseJ4 ###Ending doTestIndexAndConfigAliasReplication
[junit4] 2> 1713078 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@55524bd4{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1713078 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=158562197
[junit4] 2> 1713079 INFO (coreCloseExecutor-7038-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@e00be9a
[junit4] 2> 1713080 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@42fb399f{/solr,null,UNAVAILABLE}
[junit4] 2> 1713082 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@1b058bbe{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1713082 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=2119553471
[junit4] 2> 1713083 INFO (coreCloseExecutor-7040-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@2943edea
[junit4] 2> 1713084 INFO (TEST-TestReplicationHandler.doTestIndexAndConfigAliasReplication-seed#[A79BEAB82FF795F5]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@4e10e91e{/solr,null,UNAVAILABLE}
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestReplicationHandler -Dtests.method=doTestIndexAndConfigAliasReplication -Dtests.seed=A79BEAB82FF795F5 -Dtests.slow=true -Dtests.locale=da-DK -Dtests.timezone=Africa/Timbuktu -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[junit4] FAILURE 35.8s J1 | TestReplicationHandler.doTestIndexAndConfigAliasReplication <<<
[junit4] > Throwable #1: java.lang.AssertionError: expected:<1> but was:<0>
[junit4] > at __randomizedtesting.SeedInfo.seed([A79BEAB82FF795F5:50E804E0E91F3A13]:0)
[junit4] > at org.apache.solr.handler.TestReplicationHandler.doTestIndexAndConfigAliasReplication(TestReplicationHandler.java:1329)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1713088 INFO (SUITE-TestReplicationHandler-seed#[A79BEAB82FF795F5]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /Users/jenkins/workspace/Lucene-Solr-master-MacOSX/solr/build/solr-core/test/J1/temp/solr.handler.TestReplicationHandler_A79BEAB82FF795F5-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {name=PostingsFormat(name=Asserting), id=PostingsFormat(name=Asserting), newname=PostingsFormat(name=Asserting)}, docValues:{}, maxPointsInLeafNode=912, maxMBSortInHeap=7.03983547215896, sim=RandomSimilarity(queryNorm=true): {}, locale=da-DK, timezone=Africa/Timbuktu
[junit4] 2> NOTE: Mac OS X 10.11.6 x86_64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=3,threads=1,free=151369432,total=496996352
[junit4] 2> NOTE: All tests run in this JVM: [DirectUpdateHandlerOptimizeTest, UUIDFieldTest, PeerSyncReplicationTest, TestIndexSearcher, TestCloudManagedSchema, TestAtomicUpdateErrorCases, ShowFileRequestHandlerTest, TestFilteredDocIdSet, DeleteNodeTest, SuggesterWFSTTest, QueryParsingTest, TestJmxMonitoredMap, NotRequiredUniqueKeyTest, SpellingQueryConverterTest, TestLegacyNumericRangeQueryBuilder, PeerSyncWithIndexFingerprintCachingTest, RankQueryTest, TestSimpleTrackingShardHandler, TestSolrCLIRunExample, NoCacheHeaderTest, BadComponentTest, TestSQLHandler, StatsReloadRaceTest, BasicZkTest, TestDeleteCollectionOnDownNodes, DistributedVersionInfoTest, SmileWriterTest, CdcrUpdateLogTest, TestMiniSolrCloudCluster, ForceLeaderTest, CursorMarkTest, TestRecovery, SpellPossibilityIteratorTest, TestSolrIndexConfig, ZkStateWriterTest, CloudMLTQParserTest, TestSubQueryTransformerDistrib, TestCrossCoreJoin, TestManagedResourceStorage, FileBasedSpellCheckerTest, TestConfig, TestAnalyzeInfixSuggestions, TestSuggestSpellingConverter, TestUnifiedSolrHighlighter, TestHighFrequencyDictionaryFactory, HdfsDirectoryTest, TestImplicitCoreProperties, TestDFRSimilarityFactory, TestSolrQueryParserResource, ChaosMonkeySafeLeaderTest, TestFieldCacheReopen, SliceStateTest, TestCloudPseudoReturnFields, ChangedSchemaMergeTest, TestSolrDeletionPolicy2, TestLMJelinekMercerSimilarityFactory, TestCustomSort, TestValueSourceCache, TestLeaderElectionZkExpiry, SuggesterTSTTest, IgnoreCommitOptimizeUpdateProcessorFactoryTest, TestDistributedMissingSort, SolrCloudExampleTest, TestSimpleQParserPlugin, OpenCloseCoreStressTest, TestSSLRandomization, TestReRankQParserPlugin, TestEmbeddedSolrServerConstructors, TestJavabinTupleStreamParser, FullSolrCloudDistribCmdsTest, SimpleCollectionCreateDeleteTest, TestSchemaNameResource, TestZkChroot, TestStandardQParsers, TestFieldCacheVsDocValues, TestSubQueryTransformer, BasicAuthIntegrationTest, TestFiltering, TestComponentsName, TestSolrCoreSnapshots, RemoteQueryErrorTest, TestSolrCoreProperties, CollectionsAPISolrJTest, TestExceedMaxTermLength, TestScoreJoinQPScore, HdfsDirectoryFactoryTest, ExplicitHLLTest, TestClassicSimilarityFactory, BigEndianAscendingWordSerializerTest, ManagedSchemaRoundRobinCloudTest, TestSolrXml, TestStressRecovery, TestCollapseQParserPlugin, TestPHPSerializedResponseWriter, StatsComponentTest, HighlighterConfigTest, ConvertedLegacyTest, TestUseDocValuesAsStored, ShardRoutingCustomTest, TestNumericTerms64, TestSha256AuthenticationProvider, TestConfigSetsAPIZkFailure, TestExactStatsCache, TestConfigSetsAPI, TestIndexingPerformance, CacheHeaderTest, BasicFunctionalityTest, TestBlobHandler, SecurityConfHandlerTest, HdfsSyncSliceTest, ShufflingReplicaListTransformerTest, TestClusterProperties, TestAnalyzedSuggestions, TestReload, TestDownShardTolerantSearch, TestManagedStopFilterFactory, DistributedExpandComponentTest, TestMacros, TestDynamicFieldCollectionResource, DocValuesMissingTest, TestSolrQueryResponse, CollectionReloadTest, GraphQueryTest, TestSolr4Spatial2, BadCopyFieldTest, SharedFSAutoReplicaFailoverTest, TestRawResponseWriter, TestRequestForwarding, CdcrVersionReplicationTest, TestFoldingMultitermQuery, CloneFieldUpdateProcessorFactoryTest, HdfsTlogReplayBufferedWhileIndexingTest, HdfsRecoveryZkTest, FacetPivotSmallTest, TestDocSet, DistributedQueryComponentOptimizationTest, ResourceLoaderTest, TestDistribIDF, TestNamedUpdateProcessors, LeaderElectionIntegrationTest, TestCustomStream, BadIndexSchemaTest, SpatialRPTFieldTypeTest, TestManagedSchemaThreadSafety, TestFieldCacheSort, TestReversedWildcardFilterFactory, HdfsNNFailoverTest, TestOmitPositions, TermVectorComponentDistributedTest, TestWriterPerf, DateMathParserTest, RuleEngineTest, TestSizeLimitedDistributedMap, DirectoryFactoryTest, SuggesterTest, AsyncCallRequestStatusResponseTest, TestSolrQueryParser, DistributedFacetPivotSmallAdvancedTest, TestJoin, DistributedFacetPivotLargeTest, LoggingHandlerTest, BasicDistributedZkTest, BasicDistributedZk2Test, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest, SyncSliceTest, TestReplicationHandler]
[junit4] Completed [338/659 (1!)] on J1 in 108.54s, 15 tests, 1 failure, 1 skipped <<< FAILURES!
[...truncated 63416 lines...]