You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2017/03/10 19:53:38 UTC
[JENKINS] Lucene-Solr-Tests-master - Build # 1719 - Unstable
Build: https://builds.apache.org/job/Lucene-Solr-Tests-master/1719/
1 tests failed.
FAILED: org.apache.solr.cloud.MissingSegmentRecoveryTest.testLeaderRecovery
Error Message:
Expected a collection with one shard and two replicas null Last available state: DocCollection(MissingSegmentRecoveryTest//collections/MissingSegmentRecoveryTest/state.json/7)={ "replicationFactor":"2", "shards":{"shard1":{ "range":"80000000-7fffffff", "state":"active", "replicas":{ "core_node1":{ "core":"MissingSegmentRecoveryTest_shard1_replica1", "base_url":"http://127.0.0.1:42282/solr", "node_name":"127.0.0.1:42282_solr", "state":"active", "leader":"true"}, "core_node2":{ "core":"MissingSegmentRecoveryTest_shard1_replica2", "base_url":"http://127.0.0.1:49935/solr", "node_name":"127.0.0.1:49935_solr", "state":"down"}}}}, "router":{"name":"compositeId"}, "maxShardsPerNode":"1", "autoAddReplicas":"false"}
Stack Trace:
java.lang.AssertionError: Expected a collection with one shard and two replicas
null
Last available state: DocCollection(MissingSegmentRecoveryTest//collections/MissingSegmentRecoveryTest/state.json/7)={
"replicationFactor":"2",
"shards":{"shard1":{
"range":"80000000-7fffffff",
"state":"active",
"replicas":{
"core_node1":{
"core":"MissingSegmentRecoveryTest_shard1_replica1",
"base_url":"http://127.0.0.1:42282/solr",
"node_name":"127.0.0.1:42282_solr",
"state":"active",
"leader":"true"},
"core_node2":{
"core":"MissingSegmentRecoveryTest_shard1_replica2",
"base_url":"http://127.0.0.1:49935/solr",
"node_name":"127.0.0.1:49935_solr",
"state":"down"}}}},
"router":{"name":"compositeId"},
"maxShardsPerNode":"1",
"autoAddReplicas":"false"}
at __randomizedtesting.SeedInfo.seed([719AD5B4786C726F:21CF4DB7214DC472]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.SolrCloudTestCase.waitForState(SolrCloudTestCase.java:265)
at org.apache.solr.cloud.MissingSegmentRecoveryTest.testLeaderRecovery(MissingSegmentRecoveryTest.java:105)
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:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 12498 lines...]
[junit4] Suite: org.apache.solr.cloud.MissingSegmentRecoveryTest
[junit4] 2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/init-core-data-001
[junit4] 2> 1388444 WARN (SUITE-MissingSegmentRecoveryTest-seed#[719AD5B4786C726F]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=17 numCloses=17
[junit4] 2> 1388444 INFO (SUITE-MissingSegmentRecoveryTest-seed#[719AD5B4786C726F]-worker) [ ] o.a.s.SolrTestCaseJ4 Using TrieFields
[junit4] 2> 1388445 INFO (SUITE-MissingSegmentRecoveryTest-seed#[719AD5B4786C726F]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 1388446 INFO (SUITE-MissingSegmentRecoveryTest-seed#[719AD5B4786C726F]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001
[junit4] 2> 1388446 INFO (SUITE-MissingSegmentRecoveryTest-seed#[719AD5B4786C726F]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1388446 INFO (Thread-2980) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1388446 INFO (Thread-2980) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1388546 INFO (SUITE-MissingSegmentRecoveryTest-seed#[719AD5B4786C726F]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:55880
[junit4] 2> 1388557 INFO (jetty-launcher-2100-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1388558 INFO (jetty-launcher-2100-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@7fc44013{/solr,null,AVAILABLE}
[junit4] 2> 1388558 INFO (jetty-launcher-2100-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@76f5d3b2{HTTP/1.1,[http/1.1]}{127.0.0.1:42282}
[junit4] 2> 1388558 INFO (jetty-launcher-2100-thread-1) [ ] o.e.j.s.Server Started @1394788ms
[junit4] 2> 1388558 INFO (jetty-launcher-2100-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=42282}
[junit4] 2> 1388558 ERROR (jetty-launcher-2100-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1388558 INFO (jetty-launcher-2100-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.0.0
[junit4] 2> 1388558 INFO (jetty-launcher-2100-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1388558 INFO (jetty-launcher-2100-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1388558 INFO (jetty-launcher-2100-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-03-10T19:25:02.595Z
[junit4] 2> 1388570 INFO (jetty-launcher-2100-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1388570 INFO (jetty-launcher-2100-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1388571 INFO (jetty-launcher-2100-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@21389566{/solr,null,AVAILABLE}
[junit4] 2> 1388571 INFO (jetty-launcher-2100-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@615b7e3{HTTP/1.1,[http/1.1]}{127.0.0.1:49935}
[junit4] 2> 1388571 INFO (jetty-launcher-2100-thread-2) [ ] o.e.j.s.Server Started @1394802ms
[junit4] 2> 1388571 INFO (jetty-launcher-2100-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=49935}
[junit4] 2> 1388571 ERROR (jetty-launcher-2100-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1388571 INFO (jetty-launcher-2100-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.0.0
[junit4] 2> 1388572 INFO (jetty-launcher-2100-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1388572 INFO (jetty-launcher-2100-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1388572 INFO (jetty-launcher-2100-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-03-10T19:25:02.609Z
[junit4] 2> 1388578 INFO (jetty-launcher-2100-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1388580 INFO (jetty-launcher-2100-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:55880/solr
[junit4] 2> 1388583 INFO (jetty-launcher-2100-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:55880/solr
[junit4] 2> 1388596 INFO (jetty-launcher-2100-thread-2) [n:127.0.0.1:49935_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 1388596 INFO (jetty-launcher-2100-thread-2) [n:127.0.0.1:49935_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:49935_solr
[junit4] 2> 1388597 INFO (jetty-launcher-2100-thread-2) [n:127.0.0.1:49935_solr ] o.a.s.c.Overseer Overseer (id=97594500873191430-127.0.0.1:49935_solr-n_0000000000) starting
[junit4] 2> 1388598 INFO (jetty-launcher-2100-thread-1) [n:127.0.0.1:42282_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 1388600 INFO (jetty-launcher-2100-thread-1) [n:127.0.0.1:42282_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42282_solr
[junit4] 2> 1388600 INFO (zkCallback-2110-thread-1-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1388603 INFO (zkCallback-2112-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1388615 INFO (jetty-launcher-2100-thread-2) [n:127.0.0.1:49935_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49935_solr
[junit4] 2> 1388615 INFO (zkCallback-2110-thread-1-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1388615 INFO (zkCallback-2112-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1388687 INFO (jetty-launcher-2100-thread-1) [n:127.0.0.1:42282_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node1/.
[junit4] 2> 1388826 INFO (jetty-launcher-2100-thread-2) [n:127.0.0.1:49935_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/.
[junit4] 2> 1389514 INFO (SUITE-MissingSegmentRecoveryTest-seed#[719AD5B4786C726F]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1389515 INFO (SUITE-MissingSegmentRecoveryTest-seed#[719AD5B4786C726F]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:55880/solr ready
[junit4] 2> 1389529 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testLeaderRecovery
[junit4] 2> 1389530 INFO (qtp1440768226-12353) [n:127.0.0.1:49935_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&collection.configName=conf&maxShardsPerNode=1&name=MissingSegmentRecoveryTest&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 1389535 INFO (OverseerThreadFactory-5170-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.CreateCollectionCmd Create collection MissingSegmentRecoveryTest
[junit4] 2> 1389644 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=MissingSegmentRecoveryTest_shard1_replica1&action=CREATE&numShards=1&collection=MissingSegmentRecoveryTest&shard=shard1&wt=javabin&version=2
[junit4] 2> 1389644 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=MissingSegmentRecoveryTest_shard1_replica2&action=CREATE&numShards=1&collection=MissingSegmentRecoveryTest&shard=shard1&wt=javabin&version=2
[junit4] 2> 1389749 INFO (zkCallback-2110-thread-1-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1389749 INFO (zkCallback-2112-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1390656 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 1390656 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 1390669 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.s.IndexSchema [MissingSegmentRecoveryTest_shard1_replica1] Schema name=minimal
[junit4] 2> 1390671 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 1390672 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'MissingSegmentRecoveryTest_shard1_replica1' using configuration from collection MissingSegmentRecoveryTest
[junit4] 2> 1390672 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.s.IndexSchema [MissingSegmentRecoveryTest_shard1_replica2] Schema name=minimal
[junit4] 2> 1390672 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.SolrCore [[MissingSegmentRecoveryTest_shard1_replica1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node1/MissingSegmentRecoveryTest_shard1_replica1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node1/./MissingSegmentRecoveryTest_shard1_replica1/data/]
[junit4] 2> 1390674 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 1390674 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.CoreContainer Creating SolrCore 'MissingSegmentRecoveryTest_shard1_replica2' using configuration from collection MissingSegmentRecoveryTest
[junit4] 2> 1390674 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrCore [[MissingSegmentRecoveryTest_shard1_replica2] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/MissingSegmentRecoveryTest_shard1_replica2], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/./MissingSegmentRecoveryTest_shard1_replica2/data/]
[junit4] 2> 1390707 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1390707 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1390707 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1390707 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1390708 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1390708 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1390708 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1390708 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1390709 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.s.SolrIndexSearcher Opening [Searcher@1740ed6f[MissingSegmentRecoveryTest_shard1_replica2] main]
[junit4] 2> 1390709 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@130811db[MissingSegmentRecoveryTest_shard1_replica1] main]
[junit4] 2> 1390710 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 1390711 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 1390711 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 1390711 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1390711 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1561512016345038848
[junit4] 2> 1390711 INFO (searcherExecutor-5175-thread-1-processing-n:127.0.0.1:42282_solr x:MissingSegmentRecoveryTest_shard1_replica1 s:shard1 c:MissingSegmentRecoveryTest) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.SolrCore [MissingSegmentRecoveryTest_shard1_replica1] Registered new searcher Searcher@130811db[MissingSegmentRecoveryTest_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1390713 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 1390713 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1390713 INFO (searcherExecutor-5176-thread-1-processing-n:127.0.0.1:49935_solr x:MissingSegmentRecoveryTest_shard1_replica2 s:shard1 c:MissingSegmentRecoveryTest) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrCore [MissingSegmentRecoveryTest_shard1_replica2] Registered new searcher Searcher@1740ed6f[MissingSegmentRecoveryTest_shard1_replica2] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1390713 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1561512016347136000
[junit4] 2> 1390716 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard1: total=2 found=1 timeoutin=9999ms
[junit4] 2> 1390818 INFO (zkCallback-2110-thread-1-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1390818 INFO (zkCallback-2112-thread-3-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1391216 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1391217 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1391217 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:42282/solr/MissingSegmentRecoveryTest_shard1_replica1/
[junit4] 2> 1391217 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.PeerSync PeerSync: core=MissingSegmentRecoveryTest_shard1_replica1 url=http://127.0.0.1:42282/solr START replicas=[http://127.0.0.1:49935/solr/MissingSegmentRecoveryTest_shard1_replica2/] nUpdates=100
[junit4] 2> 1391217 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.PeerSync PeerSync: core=MissingSegmentRecoveryTest_shard1_replica1 url=http://127.0.0.1:42282/solr DONE. We have no versions. sync failed.
[junit4] 2> 1391218 INFO (qtp1440768226-12357) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.S.Request [MissingSegmentRecoveryTest_shard1_replica2] webapp=/solr path=/get params={distrib=false&qt=/get&fingerprint=false&getVersions=100&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 1391219 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.SyncStrategy Leader's attempt to sync with shard failed, moving to the next candidate
[junit4] 2> 1391219 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.ShardLeaderElectionContext We failed sync, but we have no versions - we can't sync in that case - we were active before, so become leader anyway
[junit4] 2> 1391219 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 1391221 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:42282/solr/MissingSegmentRecoveryTest_shard1_replica1/ shard1
[junit4] 2> 1391322 INFO (zkCallback-2110-thread-1-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1391323 INFO (zkCallback-2112-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1391371 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1391373 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=MissingSegmentRecoveryTest_shard1_replica1&action=CREATE&numShards=1&collection=MissingSegmentRecoveryTest&shard=shard1&wt=javabin&version=2} status=0 QTime=1728
[junit4] 2> 1391475 INFO (zkCallback-2110-thread-1-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1391475 INFO (zkCallback-2112-thread-2-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1391720 INFO (qtp1440768226-12352) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&collection.configName=conf&newCollection=true&name=MissingSegmentRecoveryTest_shard1_replica2&action=CREATE&numShards=1&collection=MissingSegmentRecoveryTest&shard=shard1&wt=javabin&version=2} status=0 QTime=2075
[junit4] 2> 1391722 INFO (qtp1440768226-12353) [n:127.0.0.1:49935_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> 1391823 INFO (zkCallback-2110-thread-1-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1391824 INFO (zkCallback-2112-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1392722 INFO (qtp1440768226-12353) [n:127.0.0.1:49935_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=2&collection.configName=conf&maxShardsPerNode=1&name=MissingSegmentRecoveryTest&action=CREATE&numShards=1&wt=javabin&version=2} status=0 QTime=3192
[junit4] 2> 1392747 INFO (qtp1440768226-12358) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.p.LogUpdateProcessorFactory [MissingSegmentRecoveryTest_shard1_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:42282/solr/MissingSegmentRecoveryTest_shard1_replica1/&wt=javabin&version=2}{add=[0 (1561512018460016640), 1 (1561512018461065216), 2 (1561512018461065217), 3 (1561512018461065218), 4 (1561512018462113792), 5 (1561512018462113793), 6 (1561512018462113794), 7 (1561512018462113795), 8 (1561512018462113796), 9 (1561512018462113797)]} 0 1
[junit4] 2> 1392748 INFO (qtp1695116199-12340) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.p.LogUpdateProcessorFactory [MissingSegmentRecoveryTest_shard1_replica1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[0 (1561512018460016640), 1 (1561512018461065216), 2 (1561512018461065217), 3 (1561512018461065218), 4 (1561512018462113792), 5 (1561512018462113793), 6 (1561512018462113794), 7 (1561512018462113795), 8 (1561512018462113796), 9 (1561512018462113797)]} 0 20
[junit4] 2> 1392754 INFO (qtp1695116199-12346) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1392754 INFO (qtp1695116199-12346) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@6687b5f2
[junit4] 2> 1392759 INFO (qtp1440768226-12351) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1392759 INFO (qtp1440768226-12351) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@3fa0156d
[junit4] 2> 1392780 INFO (qtp1695116199-12346) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@47e4e70a[MissingSegmentRecoveryTest_shard1_replica1] main]
[junit4] 2> 1392780 INFO (qtp1695116199-12346) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1392780 INFO (searcherExecutor-5175-thread-1-processing-n:127.0.0.1:42282_solr x:MissingSegmentRecoveryTest_shard1_replica1 s:shard1 c:MissingSegmentRecoveryTest r:core_node1) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.c.SolrCore [MissingSegmentRecoveryTest_shard1_replica1] Registered new searcher Searcher@47e4e70a[MissingSegmentRecoveryTest_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C10)))}
[junit4] 2> 1392780 INFO (qtp1695116199-12346) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.p.LogUpdateProcessorFactory [MissingSegmentRecoveryTest_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:42282/solr/MissingSegmentRecoveryTest_shard1_replica1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 25
[junit4] 2> 1392782 INFO (qtp1440768226-12351) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.s.SolrIndexSearcher Opening [Searcher@234c8500[MissingSegmentRecoveryTest_shard1_replica2] main]
[junit4] 2> 1392782 INFO (qtp1440768226-12351) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1392782 INFO (searcherExecutor-5176-thread-1-processing-n:127.0.0.1:49935_solr x:MissingSegmentRecoveryTest_shard1_replica2 s:shard1 c:MissingSegmentRecoveryTest r:core_node2) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrCore [MissingSegmentRecoveryTest_shard1_replica2] Registered new searcher Searcher@234c8500[MissingSegmentRecoveryTest_shard1_replica2] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C10)))}
[junit4] 2> 1392782 INFO (qtp1440768226-12351) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.p.LogUpdateProcessorFactory [MissingSegmentRecoveryTest_shard1_replica2] webapp=/solr path=/update params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from=http://127.0.0.1:42282/solr/MissingSegmentRecoveryTest_shard1_replica1/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false}{commit=} 0 23
[junit4] 2> 1392783 INFO (qtp1695116199-12345) [n:127.0.0.1:42282_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node1 x:MissingSegmentRecoveryTest_shard1_replica1] o.a.s.u.p.LogUpdateProcessorFactory [MissingSegmentRecoveryTest_shard1_replica1] webapp=/solr path=/update params={_stateVer_=MissingSegmentRecoveryTest:5&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 31
[junit4] 2> 1392785 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@615b7e3{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1392785 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=709887742
[junit4] 2> 1392786 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1392786 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 1392792 INFO (coreCloseExecutor-5185-thread-1) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrCore [MissingSegmentRecoveryTest_shard1_replica2] CLOSING SolrCore org.apache.solr.core.SolrCore@455750f2
[junit4] 2> 1392794 INFO (coreCloseExecutor-5185-thread-1) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.MissingSegmentRecoveryTest.shard1.replica2, tag=1163350258
[junit4] 2> 1392795 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.c.Overseer Overseer (id=97594500873191430-127.0.0.1:49935_solr-n_0000000000) closing
[junit4] 2> 1392795 INFO (OverseerStateUpdate-97594500873191430-127.0.0.1:49935_solr-n_0000000000) [n:127.0.0.1:49935_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:49935_solr
[junit4] 2> 1392799 WARN (zkCallback-2112-thread-2-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 1392800 INFO (zkCallback-2118-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1392800 INFO (zkCallback-2110-thread-1-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1392800 INFO (zkCallback-2110-thread-2-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:42282_solr
[junit4] 2> 1392801 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@21389566{/solr,null,UNAVAILABLE}
[junit4] 2> 1392802 INFO (zkCallback-2110-thread-2-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.Overseer Overseer (id=97594500873191428-127.0.0.1:42282_solr-n_0000000001) starting
[junit4] 2> 1392802 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1392804 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@23ce6d4b{/solr,null,AVAILABLE}
[junit4] 2> 1392804 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@c3e549e{HTTP/1.1,[http/1.1]}{127.0.0.1:49935}
[junit4] 2> 1392804 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.e.j.s.Server Started @1399035ms
[junit4] 2> 1392804 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=49935}
[junit4] 2> 1392805 ERROR (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1392808 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 7.0.0
[junit4] 2> 1392808 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1392808 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1392808 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-03-10T19:25:06.845Z
[junit4] 2> 1392810 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1392811 INFO (zkCallback-2110-thread-2-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [1])
[junit4] 2> 1392832 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:55880/solr
[junit4] 2> 1392837 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1392838 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [n:127.0.0.1:49935_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 1392839 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [n:127.0.0.1:49935_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49935_solr
[junit4] 2> 1392840 INFO (zkCallback-2118-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1392840 INFO (zkCallback-2110-thread-2-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1392843 INFO (zkCallback-2123-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1392911 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [n:127.0.0.1:49935_solr ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/.
[junit4] 2> 1392911 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [n:127.0.0.1:49935_solr ] o.a.s.c.CorePropertiesLocator Cores are: [MissingSegmentRecoveryTest_shard1_replica2]
[junit4] 2> 1392940 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 1392946 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.s.IndexSchema [MissingSegmentRecoveryTest_shard1_replica2] Schema name=minimal
[junit4] 2> 1392948 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 1392958 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.CoreContainer Creating SolrCore 'MissingSegmentRecoveryTest_shard1_replica2' using configuration from collection MissingSegmentRecoveryTest
[junit4] 2> 1392959 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrCore [[MissingSegmentRecoveryTest_shard1_replica2] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/MissingSegmentRecoveryTest_shard1_replica2], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/./MissingSegmentRecoveryTest_shard1_replica2/data/]
[junit4] 2> 1393018 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1393019 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1393019 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1393019 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1393021 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrCore [MissingSegmentRecoveryTest_shard1_replica2] CLOSING SolrCore org.apache.solr.core.SolrCore@570d02a2
[junit4] 2> 1393025 INFO (zkCallback-2123-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1393025 INFO (zkCallback-2110-thread-2-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1393026 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.MissingSegmentRecoveryTest.shard1.replica2, tag=1460470434
[junit4] 2> 1393027 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.CoreContainer Found active leader, will attempt to create fresh core and recover.
[junit4] 2> 1393028 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrCore Updating index properties... index=index.20170310112507065
[junit4] 2> 1393057 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrCore [[MissingSegmentRecoveryTest_shard1_replica2] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/MissingSegmentRecoveryTest_shard1_replica2], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/./MissingSegmentRecoveryTest_shard1_replica2/data/]
[junit4] 2> 1393060 INFO (OldIndexDirectoryCleanupThreadForCore-MissingSegmentRecoveryTest_shard1_replica2) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.DirectoryFactory Found 1 old index directories to clean-up under /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/./MissingSegmentRecoveryTest_shard1_replica2/data/ afterReload=false
[junit4] 2> 1393064 INFO (OldIndexDirectoryCleanupThreadForCore-MissingSegmentRecoveryTest_shard1_replica2) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.DirectoryFactory Deleted old index directory: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/./MissingSegmentRecoveryTest_shard1_replica2/data/index.20170310112507065
[junit4] 2> 1393064 ERROR (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.SolrIndexWriter Error closing IndexWriter
[junit4] 2> java.nio.file.NoSuchFileException: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/MissingSegmentRecoveryTest_shard1_replica2/data/index.20170310112507065/write.lock
[junit4] 2> at sun.nio.fs.UnixException.translateToIOException(UnixException.java:86)
[junit4] 2> at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:102)
[junit4] 2> at sun.nio.fs.UnixException.rethrowAsIOException(UnixException.java:107)
[junit4] 2> at sun.nio.fs.UnixFileAttributeViews$Basic.readAttributes(UnixFileAttributeViews.java:55)
[junit4] 2> at sun.nio.fs.UnixFileSystemProvider.readAttributes(UnixFileSystemProvider.java:144)
[junit4] 2> at sun.nio.fs.LinuxFileSystemProvider.readAttributes(LinuxFileSystemProvider.java:99)
[junit4] 2> at java.nio.file.Files.readAttributes(Files.java:1737)
[junit4] 2> at org.apache.lucene.store.NativeFSLockFactory$NativeFSLock.ensureValid(NativeFSLockFactory.java:177)
[junit4] 2> at org.apache.lucene.store.LockValidatingDirectoryWrapper.sync(LockValidatingDirectoryWrapper.java:67)
[junit4] 2> at org.apache.lucene.index.IndexWriter.startCommit(IndexWriter.java:4706)
[junit4] 2> at org.apache.lucene.index.IndexWriter.prepareCommitInternal(IndexWriter.java:3093)
[junit4] 2> at org.apache.lucene.index.IndexWriter.commitInternal(IndexWriter.java:3227)
[junit4] 2> at org.apache.lucene.index.IndexWriter.shutdown(IndexWriter.java:1126)
[junit4] 2> at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1169)
[junit4] 2> at org.apache.solr.update.SolrIndexWriter.close(SolrIndexWriter.java:291)
[junit4] 2> at org.apache.solr.core.SolrCore.initIndex(SolrCore.java:729)
[junit4] 2> at org.apache.solr.core.SolrCore.<init>(SolrCore.java:913)
[junit4] 2> at org.apache.solr.core.SolrCore.<init>(SolrCore.java:829)
[junit4] 2> at org.apache.solr.core.CoreContainer.processCoreCreateException(CoreContainer.java:1023)
[junit4] 2> at org.apache.solr.core.CoreContainer.create(CoreContainer.java:951)
[junit4] 2> at org.apache.solr.core.CoreContainer.lambda$load$3(CoreContainer.java:582)
[junit4] 2> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedCallable.call(InstrumentedExecutorService.java:197)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1393087 INFO (OldIndexDirectoryCleanupThreadForCore-MissingSegmentRecoveryTest_shard1_replica2) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.DirectoryFactory Found 1 old index directories to clean-up under /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/./MissingSegmentRecoveryTest_shard1_replica2/data/ afterReload=false
[junit4] 2> 1393095 INFO (OldIndexDirectoryCleanupThreadForCore-MissingSegmentRecoveryTest_shard1_replica2) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.DirectoryFactory Deleted old index directory: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/./MissingSegmentRecoveryTest_shard1_replica2/data/index
[junit4] 2> 1393123 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 1393123 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1393124 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1393124 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1393125 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.c.SolrCore [MissingSegmentRecoveryTest_shard1_replica2] CLOSING SolrCore org.apache.solr.core.SolrCore@101f0c4b
[junit4] 2> 1393142 INFO (coreLoadExecutor-5194-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr c:MissingSegmentRecoveryTest s:shard1 r:core_node2 x:MissingSegmentRecoveryTest_shard1_replica2] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.MissingSegmentRecoveryTest.shard1.replica2, tag=270470219
[junit4] 2> 1393143 ERROR (coreContainerWorkExecutor-5190-thread-1-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.CoreContainer Error waiting for SolrCore to be created
[junit4] 2> java.util.concurrent.ExecutionException: org.apache.solr.common.SolrException: Unable to create core [MissingSegmentRecoveryTest_shard1_replica2]
[junit4] 2> at java.util.concurrent.FutureTask.report(FutureTask.java:122)
[junit4] 2> at java.util.concurrent.FutureTask.get(FutureTask.java:192)
[junit4] 2> at org.apache.solr.core.CoreContainer.lambda$load$4(CoreContainer.java:610)
[junit4] 2> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> Caused by: org.apache.solr.common.SolrException: Unable to create core [MissingSegmentRecoveryTest_shard1_replica2]
[junit4] 2> at org.apache.solr.core.CoreContainer.create(CoreContainer.java:964)
[junit4] 2> at org.apache.solr.core.CoreContainer.lambda$load$3(CoreContainer.java:582)
[junit4] 2> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedCallable.call(InstrumentedExecutorService.java:197)
[junit4] 2> ... 5 more
[junit4] 2> Caused by: org.apache.solr.common.SolrException: Error opening new searcher
[junit4] 2> at org.apache.solr.core.SolrCore.<init>(SolrCore.java:966)
[junit4] 2> at org.apache.solr.core.SolrCore.<init>(SolrCore.java:829)
[junit4] 2> at org.apache.solr.core.CoreContainer.processCoreCreateException(CoreContainer.java:1023)
[junit4] 2> at org.apache.solr.core.CoreContainer.create(CoreContainer.java:951)
[junit4] 2> ... 7 more
[junit4] 2> Suppressed: org.apache.solr.common.SolrException: Error opening new searcher
[junit4] 2> at org.apache.solr.core.SolrCore.<init>(SolrCore.java:966)
[junit4] 2> at org.apache.solr.core.SolrCore.<init>(SolrCore.java:829)
[junit4] 2> at org.apache.solr.core.CoreContainer.create(CoreContainer.java:949)
[junit4] 2> ... 7 more
[junit4] 2> Caused by: org.apache.solr.common.SolrException: Error opening new searcher
[junit4] 2> at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:2015)
[junit4] 2> at org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:2135)
[junit4] 2> at org.apache.solr.core.SolrCore.initSearcher(SolrCore.java:1055)
[junit4] 2> at org.apache.solr.core.SolrCore.<init>(SolrCore.java:939)
[junit4] 2> ... 9 more
[junit4] 2> Caused by: org.apache.lucene.index.CorruptIndexException: Unexpected file read error while reading index. (resource=BufferedChecksumIndexInput(MMapIndexInput(path="/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/MissingSegmentRecoveryTest_shard1_replica2/data/index/segments_2")))
[junit4] 2> at org.apache.lucene.index.SegmentInfos.readCommit(SegmentInfos.java:292)
[junit4] 2> at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:928)
[junit4] 2> at org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:125)
[junit4] 2> at org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:100)
[junit4] 2> at org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:240)
[junit4] 2> at org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:114)
[junit4] 2> at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:1976)
[junit4] 2> ... 12 more
[junit4] 2> Caused by: java.io.EOFException: read past EOF: MMapIndexInput(path="/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/MissingSegmentRecoveryTest_shard1_replica2/data/index/segments_2")
[junit4] 2> at org.apache.lucene.store.ByteBufferIndexInput.readByte(ByteBufferIndexInput.java:75)
[junit4] 2> at org.apache.lucene.store.BufferedChecksumIndexInput.readByte(BufferedChecksumIndexInput.java:41)
[junit4] 2> at org.apache.lucene.store.DataInput.readInt(DataInput.java:101)
[junit4] 2> at org.apache.lucene.index.SegmentInfos.readCommit(SegmentInfos.java:302)
[junit4] 2> at org.apache.lucene.index.SegmentInfos.readCommit(SegmentInfos.java:290)
[junit4] 2> ... 18 more
[junit4] 2> Caused by: org.apache.solr.common.SolrException: Error opening new searcher
[junit4] 2> at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:2015)
[junit4] 2> at org.apache.solr.core.SolrCore.getSearcher(SolrCore.java:2135)
[junit4] 2> at org.apache.solr.core.SolrCore.initSearcher(SolrCore.java:1055)
[junit4] 2> at org.apache.solr.core.SolrCore.<init>(SolrCore.java:939)
[junit4] 2> ... 10 more
[junit4] 2> Caused by: org.apache.lucene.index.IndexNotFoundException: no segments* file found in LockValidatingDirectoryWrapper(MMapDirectory@/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001/tempDir-001/node2/MissingSegmentRecoveryTest_shard1_replica2/data/index.20170310112507065 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7583147c): files: [write.lock]
[junit4] 2> at org.apache.lucene.index.IndexWriter.<init>(IndexWriter.java:923)
[junit4] 2> at org.apache.solr.update.SolrIndexWriter.<init>(SolrIndexWriter.java:125)
[junit4] 2> at org.apache.solr.update.SolrIndexWriter.create(SolrIndexWriter.java:100)
[junit4] 2> at org.apache.solr.update.DefaultSolrCoreState.createMainIndexWriter(DefaultSolrCoreState.java:240)
[junit4] 2> at org.apache.solr.update.DefaultSolrCoreState.getIndexWriter(DefaultSolrCoreState.java:114)
[junit4] 2> at org.apache.solr.core.SolrCore.openNewSearcher(SolrCore.java:1976)
[junit4] 2> ... 13 more
[junit4] 2> 1483663 INFO (qtp1836828980-12419) [n:127.0.0.1:49935_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=MissingSegmentRecoveryTest&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 1483669 INFO (OverseerThreadFactory-5188-thread-1-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.OverseerCollectionMessageHandler Executing Collection Cmd : action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true
[junit4] 2> 1483670 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.MissingSegmentRecoveryTest.shard1.replica1, tag=null
[junit4] 2> 1483670 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr ] o.a.s.c.SolrCore [MissingSegmentRecoveryTest_shard1_replica1] CLOSING SolrCore org.apache.solr.core.SolrCore@5ad8eeea
[junit4] 2> 1483672 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.MissingSegmentRecoveryTest.shard1.replica1, tag=1524166378
[junit4] 2> 1483672 INFO (qtp1836828980-12421) [n:127.0.0.1:49935_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=MissingSegmentRecoveryTest_shard1_replica2&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=1
[junit4] 2> 1483676 INFO (qtp1695116199-12342) [n:127.0.0.1:42282_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={deleteInstanceDir=true&core=MissingSegmentRecoveryTest_shard1_replica1&qt=/admin/cores&deleteDataDir=true&action=UNLOAD&wt=javabin&version=2} status=0 QTime=7
[junit4] 2> 1483678 INFO (zkCallback-2123-thread-2-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1483780 INFO (zkCallback-2123-thread-2-processing-n:127.0.0.1:49935_solr) [n:127.0.0.1:49935_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDeleted path:/collections/MissingSegmentRecoveryTest/state.json] for collection [MissingSegmentRecoveryTest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1484380 INFO (qtp1836828980-12419) [n:127.0.0.1:49935_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=MissingSegmentRecoveryTest&action=DELETE&wt=javabin&version=2} status=0 QTime=716
[junit4] 2> 1484380 INFO (TEST-MissingSegmentRecoveryTest.testLeaderRecovery-seed#[719AD5B4786C726F]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testLeaderRecovery
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=MissingSegmentRecoveryTest -Dtests.method=testLeaderRecovery -Dtests.seed=719AD5B4786C726F -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=ar-DZ -Dtests.timezone=SystemV/PST8PDT -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[junit4] FAILURE 94.9s J2 | MissingSegmentRecoveryTest.testLeaderRecovery <<<
[junit4] > Throwable #1: java.lang.AssertionError: Expected a collection with one shard and two replicas
[junit4] > null
[junit4] > Last available state: DocCollection(MissingSegmentRecoveryTest//collections/MissingSegmentRecoveryTest/state.json/7)={
[junit4] > "replicationFactor":"2",
[junit4] > "shards":{"shard1":{
[junit4] > "range":"80000000-7fffffff",
[junit4] > "state":"active",
[junit4] > "replicas":{
[junit4] > "core_node1":{
[junit4] > "core":"MissingSegmentRecoveryTest_shard1_replica1",
[junit4] > "base_url":"http://127.0.0.1:42282/solr",
[junit4] > "node_name":"127.0.0.1:42282_solr",
[junit4] > "state":"active",
[junit4] > "leader":"true"},
[junit4] > "core_node2":{
[junit4] > "core":"MissingSegmentRecoveryTest_shard1_replica2",
[junit4] > "base_url":"http://127.0.0.1:49935/solr",
[junit4] > "node_name":"127.0.0.1:49935_solr",
[junit4] > "state":"down"}}}},
[junit4] > "router":{"name":"compositeId"},
[junit4] > "maxShardsPerNode":"1",
[junit4] > "autoAddReplicas":"false"}
[junit4] > at __randomizedtesting.SeedInfo.seed([719AD5B4786C726F:21CF4DB7214DC472]:0)
[junit4] > at org.apache.solr.cloud.SolrCloudTestCase.waitForState(SolrCloudTestCase.java:265)
[junit4] > at org.apache.solr.cloud.MissingSegmentRecoveryTest.testLeaderRecovery(MissingSegmentRecoveryTest.java:105)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 1484384 INFO (jetty-closer-2101-thread-2) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@c3e549e{HTTP/1.1,[http/1.1]}{127.0.0.1:49935}
[junit4] 2> 1484384 INFO (jetty-closer-2101-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@76f5d3b2{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 1484387 INFO (jetty-closer-2101-thread-2) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=2130737672
[junit4] 2> 1484387 INFO (jetty-closer-2101-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1484388 INFO (jetty-closer-2101-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=707345148
[junit4] 2> 1484388 INFO (jetty-closer-2101-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1484388 INFO (jetty-closer-2101-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 1484389 INFO (jetty-closer-2101-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 1484390 INFO (jetty-closer-2101-thread-1) [ ] o.a.s.c.Overseer Overseer (id=97594500873191428-127.0.0.1:42282_solr-n_0000000001) closing
[junit4] 2> 1484390 INFO (OverseerStateUpdate-97594500873191428-127.0.0.1:42282_solr-n_0000000001) [n:127.0.0.1:42282_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:42282_solr
[junit4] 2> 1484391 INFO (zkCallback-2110-thread-55-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1484392 INFO (jetty-closer-2101-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@23ce6d4b{/solr,null,UNAVAILABLE}
[junit4] 2> 1485891 WARN (zkCallback-2110-thread-55-processing-n:127.0.0.1:42282_solr) [n:127.0.0.1:42282_solr ] o.a.s.c.c.ZkStateReader ZooKeeper watch triggered, but Solr cannot talk to ZK: [KeeperErrorCode = Session expired for /live_nodes]
[junit4] 2> 1485892 INFO (jetty-closer-2101-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@7fc44013{/solr,null,UNAVAILABLE}
[junit4] 2> 1485893 INFO (SUITE-MissingSegmentRecoveryTest-seed#[719AD5B4786C726F]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:55880 55880
[junit4] 2> 1486117 INFO (Thread-2980) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:55880 55880
[junit4] 2> 1486117 WARN (Thread-2980) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 4 /solr/aliases.json
[junit4] 2> 4 /solr/clusterprops.json
[junit4] 2> 3 /solr/security.json
[junit4] 2> 2 /solr/configs/conf
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 4 /solr/clusterstate.json
[junit4] 2> 4 /solr/collections/MissingSegmentRecoveryTest/state.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 92 /solr/overseer/collection-queue-work
[junit4] 2> 12 /solr/overseer/queue
[junit4] 2> 4 /solr/collections
[junit4] 2> 3 /solr/live_nodes
[junit4] 2> 3 /solr/overseer/queue-work
[junit4] 2>
[junit4] 2> 1486118 INFO (SUITE-MissingSegmentRecoveryTest-seed#[719AD5B4786C726F]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J2/temp/solr.cloud.MissingSegmentRecoveryTest_719AD5B4786C726F-001
[junit4] 2> NOTE: test params are: codec=Lucene70, sim=RandomSimilarity(queryNorm=false): {}, locale=ar-DZ, timezone=SystemV/PST8PDT
[junit4] 2> NOTE: Linux 3.13.0-85-generic amd64/Oracle Corporation 1.8.0_121 (64-bit)/cpus=4,threads=1,free=103351976,total=528482304
[junit4] 2> NOTE: All tests run in this JVM: [TestQueryWrapperFilter, TestManagedResource, SolrPluginUtilsTest, UpdateParamsTest, RemoteQueryErrorTest, SimpleFacetsTest, CircularListTest, TestCustomStream, HdfsChaosMonkeyNothingIsSafeTest, BadIndexSchemaTest, TestLMDirichletSimilarityFactory, TestExactSharedStatsCache, TestFieldCacheSortRandom, RAMDirectoryFactoryTest, TestCollationField, TestWriterPerf, TolerantUpdateProcessorTest, TestDocSet, SmileWriterTest, AtomicUpdatesTest, DistributedExpandComponentTest, FieldMutatingUpdateProcessorTest, TestDefaultSearchFieldResource, TestQuerySenderNoQuery, TestBackupRepositoryFactory, RulesTest, JsonValidatorTest, TestFieldCollectionResource, CloudExitableDirectoryReaderTest, SolrSlf4jReporterTest, TestLeaderInitiatedRecoveryThread, TestReqParamsAPI, TestRebalanceLeaders, TestReloadAndDeleteDocs, StressHdfsTest, VMParamsZkACLAndCredentialsProvidersTest, TestSolrCloudWithKerberosAlt, TestMacroExpander, TestSchemalessBufferedUpdates, FieldAnalysisRequestHandlerTest, CloudMLTQParserTest, BasicAuthIntegrationTest, TestIndexingPerformance, CdcrUpdateLogTest, RequestHandlersTest, FullSolrCloudDistribCmdsTest, TestCloudPseudoReturnFields, TestStandardQParsers, DistributedFacetPivotLongTailTest, OverseerTest, LukeRequestHandlerTest, HdfsDirectoryTest, BinaryUpdateRequestHandlerTest, DocValuesMultiTest, PrimitiveFieldTypeTest, LeaderElectionTest, UnloadDistributedZkTest, BlockJoinFacetRandomTest, SuggestComponentContextFilterQueryTest, StatsComponentTest, TestMissingGroups, ClassificationUpdateProcessorTest, TestSolrDynamicMBean, DeleteLastCustomShardedReplicaTest, SliceStateTest, UpdateLogTest, DebugComponentTest, ZkStateWriterTest, DateFieldTest, ConjunctionSolrSpellCheckerTest, TestOnReconnectListenerSupport, SubstringBytesRefFilterTest, HdfsNNFailoverTest, SolrIndexConfigTest, TestXmlQParser, SolrCloudExampleTest, MigrateRouteKeyTest, DistributedFacetPivotWhiteBoxTest, PreAnalyzedFieldManagedSchemaCloudTest, AsyncCallRequestStatusResponseTest, TestManagedSchemaThreadSafety, TestRecovery, TestEmbeddedSolrServerSchemaAPI, HighlighterConfigTest, TestMergePolicyConfig, SharedFSAutoReplicaFailoverUtilsTest, SolrTestCaseJ4Test, HttpPartitionTest, TestMiniSolrCloudCluster, TestSlowCompositeReaderWrapper, HLLUtilTest, TestSystemCollAutoCreate, ActionThrottleTest, OutOfBoxZkACLAndCredentialsProvidersTest, TestCSVResponseWriter, CoreAdminRequestStatusTest, ShowFileRequestHandlerTest, AutoCommitTest, TestConfigReload, DirectUpdateHandlerOptimizeTest, CdcrReplicationDistributedZkTest, TestDFISimilarityFactory, TestJavabinTupleStreamParser, CurrencyFieldXmlFileTest, DeleteShardTest, TestHdfsCloudBackupRestore, TestCoreDiscovery, SolrCoreCheckLockOnStartupTest, SaslZkACLProviderTest, DocValuesMissingTest, TestFieldCache, TestStressInPlaceUpdates, TestInitQParser, SuggesterTest, TestExpandComponent, TestRealTimeGet, TestReload, SolrCoreTest, ConvertedLegacyTest, TestSort, DirectUpdateHandlerTest, TestIndexSearcher, HighlighterTest, CoreAdminHandlerTest, SpatialFilterTest, TestCSVLoader, SchemaVersionSpecificBehaviorTest, DefaultValueUpdateProcessorTest, StatelessScriptUpdateProcessorFactoryTest, DirectSolrSpellCheckerTest, TestQueryTypes, XmlUpdateRequestHandlerTest, TermVectorComponentTest, TestSolrQueryParser, IndexSchemaTest, MBeansHandlerTest, UniqFieldsUpdateProcessorFactoryTest, PingRequestHandlerTest, ExternalFileFieldSortTest, DirectSolrConnectionTest, TestPhraseSuggestions, SynonymTokenizerTest, TestXIncludeConfig, EchoParamsTest, TestPerFieldSimilarity, ResourceLoaderTest, TestFastOutputStream, TestFastLRUCache, ChaosMonkeyNothingIsSafeTest, TestTolerantSearch, AliasIntegrationTest, CollectionReloadTest, CollectionStateFormat2Test, CollectionsAPIAsyncDistributedZkTest, DeleteStatusTest, DistribJoinFromCollectionTest, DistributedVersionInfoTest, LeaderFailureAfterFreshStartTest, LeaderInitiatedRecoveryOnShardRestartTest, MissingSegmentRecoveryTest]
[junit4] Completed [505/695 (1!)] on J2 in 97.69s, 1 test, 1 failure <<< FAILURES!
[...truncated 63212 lines...]
[JENKINS] Lucene-Solr-Tests-master - Build # 1720 - Still Unstable
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-Tests-master/1720/
1 tests failed.
FAILED: org.apache.solr.TestDistributedSearch.test
Error Message:
Expected to find shardAddress in the up shard info: {error=org.apache.solr.client.solrj.SolrServerException: No live SolrServers available to handle this request,trace=org.apache.solr.client.solrj.SolrServerException: No live SolrServers available to handle this request at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:416) at org.apache.solr.handler.component.HttpShardHandlerFactory.makeLoadBalancedRequest(HttpShardHandlerFactory.java:259) at org.apache.solr.handler.component.HttpShardHandler.lambda$submit$0(HttpShardHandler.java:166) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176) at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745) ,time=2}
Stack Trace:
java.lang.AssertionError: Expected to find shardAddress in the up shard info: {error=org.apache.solr.client.solrj.SolrServerException: No live SolrServers available to handle this request,trace=org.apache.solr.client.solrj.SolrServerException: No live SolrServers available to handle this request
at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:416)
at org.apache.solr.handler.component.HttpShardHandlerFactory.makeLoadBalancedRequest(HttpShardHandlerFactory.java:259)
at org.apache.solr.handler.component.HttpShardHandler.lambda$submit$0(HttpShardHandler.java:166)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
,time=2}
at __randomizedtesting.SeedInfo.seed([F77419D33FBE9D05:7F2026099142F0FD]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.apache.solr.TestDistributedSearch.comparePartialResponses(TestDistributedSearch.java:1186)
at org.apache.solr.TestDistributedSearch.queryPartialResults(TestDistributedSearch.java:1127)
at org.apache.solr.TestDistributedSearch.test(TestDistributedSearch.java:987)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsRepeatStatement.callStatement(BaseDistributedSearchTestCase.java:1011)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:960)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 11417 lines...]
[junit4] Suite: org.apache.solr.TestDistributedSearch
[junit4] 2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/init-core-data-001
[junit4] 2> 485610 WARN (SUITE-TestDistributedSearch-seed#[F77419D33FBE9D05]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=1 numCloses=1
[junit4] 2> 485610 INFO (SUITE-TestDistributedSearch-seed#[F77419D33FBE9D05]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields
[junit4] 2> 485611 INFO (SUITE-TestDistributedSearch-seed#[F77419D33FBE9D05]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl=https://issues.apache.org/jira/browse/SOLR-9061)
[junit4] 2> 485611 INFO (SUITE-TestDistributedSearch-seed#[F77419D33FBE9D05]-worker) [ ] o.a.s.BaseDistributedSearchTestCase Setting hostContext system property: /tl/v
[junit4] 2> 485680 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/tempDir-001/control/cores/collection1
[junit4] 2> 485681 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 485685 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@6bdc2643{/tl/v,null,AVAILABLE}
[junit4] 2> 485691 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@5454a842{HTTP/1.1,[http/1.1]}{127.0.0.1:40877}
[junit4] 2> 485691 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.Server Started @489321ms
[junit4] 2> 485691 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/tl/v, hostPort=40877, coreRootDirectory=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/tempDir-001/control/cores}
[junit4] 2> 485691 ERROR (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 485691 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.0.0
[junit4] 2> 485691 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 485691 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 485691 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-03-10T21:56:05.206Z
[junit4] 2> 485692 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/tempDir-001/control/solr.xml
[junit4] 2> 485718 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/tempDir-001/control/cores
[junit4] 2> 485718 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 485724 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/core/src/test-files/solr/collection1/lib, /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 485762 WARN (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.c.Config Beginning with Solr 5.5, <mergePolicy> is deprecated, use <mergePolicyFactory> instead.
[junit4] 2> 485763 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 485783 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 485868 WARN (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] default search field in schema is text. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 485870 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 485874 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from configset /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/core/src/test-files/solr/collection1
[junit4] 2> 485875 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/core/src/test-files/solr/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/tempDir-001/control/cores/collection1/data/]
[junit4] 2> 485875 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3451f14
[junit4] 2> 485875 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=35, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.2584945758924475]
[junit4] 2> 485910 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 485910 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 485911 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 485911 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 485911 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=23, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.7208607164486917]
[junit4] 2> 485911 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@2557f16e[collection1] main]
[junit4] 2> 485911 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 485917 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 485998 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 485999 INFO (coreLoadExecutor-3274-thread-1) [ x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1561521517246808064
[junit4] 2> 486017 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 486018 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 486019 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 486019 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 486019 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 486019 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 486020 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 486020 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 486021 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 486024 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@2557f16e[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 486263 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/tempDir-001/shard0/cores/collection1
[junit4] 2> 486264 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 486265 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@5185ca3b{/tl/v,null,AVAILABLE}
[junit4] 2> 486265 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1999ba69{HTTP/1.1,[http/1.1]}{127.0.0.1:54981}
[junit4] 2> 486265 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.Server Started @489895ms
[junit4] 2> 486265 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/tl/v, hostPort=54981, coreRootDirectory=/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/tempDir-001/shard0/cores}
[junit4] 2> 486265 ERROR (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 486265 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.0.0
[junit4] 2> 486265 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 486265 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 486265 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-03-10T21:56:05.780Z
[junit4] 2> 486266 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/tempDir-001/shard0/solr.xml
[junit4] 2> 486320 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/tempDir-001/shard0/cores
[junit4] 2> 486320 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 486333 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/core/src/test-files/solr/collection1/lib, /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 486446 WARN (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.c.Config Beginning with Solr 5.5, <mergePolicy> is deprecated, use <mergePolicyFactory> instead.
[junit4] 2> 486448 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.0.0
[junit4] 2> 486526 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 486812 WARN (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] default search field in schema is text. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 486831 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 486846 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from configset /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/core/src/test-files/solr/collection1
[junit4] 2> 486873 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/core/src/test-files/solr/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001/tempDir-001/shard0/cores/collection1/data/]
[junit4] 2> 486874 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@3451f14
[junit4] 2> 486874 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=35, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.2584945758924475]
[junit4] 2> 487115 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 487115 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 487115 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 487115 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 487119 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=23, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.7208607164486917]
[junit4] 2> 487149 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@13896d7[collection1] main]
[junit4] 2> 487150 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 487169 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 487332 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 487332 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 487332 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 487332 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 487332 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 487333 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 487333 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 487333 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 487333 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 487333 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 487334 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@13896d7[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 487335 INFO (coreLoadExecutor-3285-thread-1) [ x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1561521518647705600
[junit4] 2> 487593 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.SolrTestCaseJ4 ###Starting test
[junit4] 2> 487599 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{deleteByQuery=*:* (-1561521518923481088)} 0 1
[junit4] 2> 487615 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{deleteByQuery=*:* (-1561521518939209728)} 0 1
[junit4] 2> 487622 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[1 (1561521518942355456)]} 0 6
[junit4] 2> 487624 INFO (qtp816044000-6292) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[1 (1561521518949695488)]} 0 1
[junit4] 2> 487625 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[2 (1561521518951792640)]} 0 0
[junit4] 2> 487626 INFO (qtp816044000-6292) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[2 (1561521518952841216)]} 0 0
[junit4] 2> 487627 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[3 (1561521518953889792)]} 0 0
[junit4] 2> 487628 INFO (qtp816044000-6292) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[3 (1561521518953889792)]} 0 0
[junit4] 2> 487629 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[4 (1561521518954938368)]} 0 0
[junit4] 2> 487630 INFO (qtp816044000-6292) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[4 (1561521518955986944)]} 0 0
[junit4] 2> 487631 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[5 (1561521518957035520)]} 0 0
[junit4] 2> 487632 INFO (qtp816044000-6292) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[5 (1561521518958084096)]} 0 0
[junit4] 2> 487632 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[6 (1561521518959132672)]} 0 0
[junit4] 2> 487633 INFO (qtp816044000-6292) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[6 (1561521518960181248)]} 0 0
[junit4] 2> 487634 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[7 (1561521518961229824)]} 0 0
[junit4] 2> 487635 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[7 (1561521518962278400)]} 0 0
[junit4] 2> 487654 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[8 (1561521518963326976)]} 0 18
[junit4] 2> 487655 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[8 (1561521518983249920)]} 0 0
[junit4] 2> 487657 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[9 (1561521518984298496)]} 0 0
[junit4] 2> 487657 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[9 (1561521518985347072)]} 0 0
[junit4] 2> 487658 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 487658 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@26e8d515
[junit4] 2> 487682 INFO (qtp452615839-6276) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6e1d8cc5[collection1] main]
[junit4] 2> 487684 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@6e1d8cc5[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C9)))}
[junit4] 2> 487684 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 487684 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 26
[junit4] 2> 487685 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 487685 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@2a2e1756
[junit4] 2> 487691 INFO (qtp816044000-6288) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@203df7af[collection1] main]
[junit4] 2> 487693 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@203df7af[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C9)))}
[junit4] 2> 487693 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 487693 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 8
[junit4] 2> 487721 INFO (qtp452615839-6278) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[10 (1561521519024144384)]} 0 27
[junit4] 2> 487725 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[10 (1561521519053504512)]} 0 2
[junit4] 2> 487726 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[11 (1561521519057698816)]} 0 0
[junit4] 2> 487727 INFO (qtp816044000-6292) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[11 (1561521519058747392)]} 0 0
[junit4] 2> 487728 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[12 (1561521519059795968)]} 0 0
[junit4] 2> 487729 INFO (qtp816044000-6292) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[12 (1561521519060844544)]} 0 0
[junit4] 2> 487734 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[13 (1561521519065038848)]} 0 0
[junit4] 2> 487735 INFO (qtp816044000-6292) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[13 (1561521519067136000)]} 0 0
[junit4] 2> 487736 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[1001 (1561521519068184576)]} 0 0
[junit4] 2> 487737 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[1001 (1561521519069233152)]} 0 0
[junit4] 2> 487738 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[14 (1561521519070281728)]} 0 0
[junit4] 2> 487741 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[14 (1561521519073427456)]} 0 0
[junit4] 2> 487742 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[15 (1561521519073427456)]} 0 0
[junit4] 2> 487742 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[15 (1561521519074476032)]} 0 0
[junit4] 2> 487743 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[16 (1561521519075524608)]} 0 0
[junit4] 2> 487744 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[16 (1561521519076573184)]} 0 0
[junit4] 2> 487745 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[17 (1561521519077621760)]} 0 0
[junit4] 2> 487746 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[17 (1561521519078670336)]} 0 0
[junit4] 2> 487747 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[100 (1561521519079718912)]} 0 0
[junit4] 2> 487748 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[100 (1561521519079718912)]} 0 0
[junit4] 2> 487748 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[101 (1561521519080767488)]} 0 0
[junit4] 2> 487749 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[101 (1561521519081816064)]} 0 0
[junit4] 2> 487750 INFO (qtp452615839-6278) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[102 (1561521519082864640)]} 0 0
[junit4] 2> 487751 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[102 (1561521519082864640)]} 0 0
[junit4] 2> 487751 INFO (qtp452615839-6278) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[103 (1561521519083913216)]} 0 0
[junit4] 2> 487754 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[103 (1561521519087058944)]} 0 1
[junit4] 2> 487767 INFO (qtp452615839-6278) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[104 (1561521519100690432)]} 0 6
[junit4] 2> 487769 INFO (qtp816044000-6295) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[104 (1561521519101739008)]} 0 0
[junit4] 2> 487769 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[105 (1561521519102787584)]} 0 0
[junit4] 2> 487770 INFO (qtp816044000-6292) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[105 (1561521519103836160)]} 0 0
[junit4] 2> 487782 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[106 (1561521519115370496)]} 0 0
[junit4] 2> 487801 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[106 (1561521519116419072)]} 0 18
[junit4] 2> 487802 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[107 (1561521519137390592)]} 0 0
[junit4] 2> 487803 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[107 (1561521519138439168)]} 0 0
[junit4] 2> 487804 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[108 (1561521519139487744)]} 0 0
[junit4] 2> 487806 INFO (qtp816044000-6294) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[108 (1561521519141584896)]} 0 0
[junit4] 2> 487807 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[109 (1561521519141584896)]} 0 0
[junit4] 2> 487807 INFO (qtp816044000-6294) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[109 (1561521519142633472)]} 0 0
[junit4] 2> 487808 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[110 (1561521519143682048)]} 0 0
[junit4] 2> 487809 INFO (qtp816044000-6294) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[110 (1561521519144730624)]} 0 0
[junit4] 2> 487810 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[111 (1561521519144730624)]} 0 0
[junit4] 2> 487810 INFO (qtp816044000-6294) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[111 (1561521519145779200)]} 0 0
[junit4] 2> 487811 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[112 (1561521519146827776)]} 0 0
[junit4] 2> 487812 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[112 (1561521519147876352)]} 0 0
[junit4] 2> 487813 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[113 (1561521519148924928)]} 0 0
[junit4] 2> 487814 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[113 (1561521519149973504)]} 0 0
[junit4] 2> 487815 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[114 (1561521519149973504)]} 0 0
[junit4] 2> 487815 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[114 (1561521519151022080)]} 0 0
[junit4] 2> 487816 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[115 (1561521519152070656)]} 0 0
[junit4] 2> 487817 INFO (qtp816044000-6295) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[115 (1561521519153119232)]} 0 0
[junit4] 2> 487818 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[116 (1561521519153119232)]} 0 0
[junit4] 2> 487818 INFO (qtp816044000-6295) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[116 (1561521519154167808)]} 0 0
[junit4] 2> 487819 INFO (qtp452615839-6275) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[117 (1561521519155216384)]} 0 0
[junit4] 2> 487820 INFO (qtp816044000-6295) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[117 (1561521519155216384)]} 0 0
[junit4] 2> 487820 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[118 (1561521519156264960)]} 0 0
[junit4] 2> 487821 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[118 (1561521519157313536)]} 0 0
[junit4] 2> 487822 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[119 (1561521519158362112)]} 0 0
[junit4] 2> 487823 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[119 (1561521519158362112)]} 0 0
[junit4] 2> 487823 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[120 (1561521519159410688)]} 0 0
[junit4] 2> 487824 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[120 (1561521519160459264)]} 0 0
[junit4] 2> 487825 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[121 (1561521519161507840)]} 0 0
[junit4] 2> 487826 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[121 (1561521519161507840)]} 0 0
[junit4] 2> 487826 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[122 (1561521519162556416)]} 0 0
[junit4] 2> 487827 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[122 (1561521519163604992)]} 0 0
[junit4] 2> 487828 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[123 (1561521519164653568)]} 0 0
[junit4] 2> 487829 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[123 (1561521519164653568)]} 0 0
[junit4] 2> 487829 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[124 (1561521519165702144)]} 0 0
[junit4] 2> 487830 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[124 (1561521519166750720)]} 0 0
[junit4] 2> 487831 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[125 (1561521519166750720)]} 0 0
[junit4] 2> 487831 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[125 (1561521519167799296)]} 0 0
[junit4] 2> 487832 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[126 (1561521519168847872)]} 0 0
[junit4] 2> 487833 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[126 (1561521519169896448)]} 0 0
[junit4] 2> 487834 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[127 (1561521519169896448)]} 0 0
[junit4] 2> 487834 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[127 (1561521519170945024)]} 0 0
[junit4] 2> 487835 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[128 (1561521519171993600)]} 0 0
[junit4] 2> 487836 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[128 (1561521519173042176)]} 0 0
[junit4] 2> 487837 INFO (qtp452615839-6274) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[129 (1561521519173042176)]} 0 0
[junit4] 2> 487843 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[129 (1561521519179333632)]} 0 0
[junit4] 2> 487843 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[130 (1561521519180382208)]} 0 0
[junit4] 2> 487844 INFO (qtp816044000-6295) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[130 (1561521519181430784)]} 0 0
[junit4] 2> 487845 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[131 (1561521519182479360)]} 0 0
[junit4] 2> 487846 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[131 (1561521519183527936)]} 0 0
[junit4] 2> 487847 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[132 (1561521519184576512)]} 0 0
[junit4] 2> 487848 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[132 (1561521519184576512)]} 0 0
[junit4] 2> 487848 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[133 (1561521519185625088)]} 0 0
[junit4] 2> 487849 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[133 (1561521519186673664)]} 0 0
[junit4] 2> 487850 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[134 (1561521519187722240)]} 0 0
[junit4] 2> 487851 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[134 (1561521519187722240)]} 0 0
[junit4] 2> 487851 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[135 (1561521519188770816)]} 0 0
[junit4] 2> 487852 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[135 (1561521519189819392)]} 0 0
[junit4] 2> 487853 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[136 (1561521519190867968)]} 0 0
[junit4] 2> 487853 INFO (qtp816044000-6288) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[136 (1561521519190867968)]} 0 0
[junit4] 2> 487854 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[137 (1561521519191916544)]} 0 0
[junit4] 2> 487855 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[137 (1561521519192965120)]} 0 0
[junit4] 2> 487856 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[138 (1561521519192965120)]} 0 0
[junit4] 2> 487857 INFO (qtp816044000-6295) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[138 (1561521519195062272)]} 0 0
[junit4] 2> 487858 INFO (qtp452615839-6277) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[139 (1561521519195062272)]} 0 0
[junit4] 2> 487859 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[139 (1561521519196110848)]} 0 0
[junit4] 2> 487859 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[140 (1561521519197159424)]} 0 0
[junit4] 2> 487861 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[140 (1561521519199256576)]} 0 0
[junit4] 2> 487862 INFO (qtp452615839-6278) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[141 (1561521519199256576)]} 0 0
[junit4] 2> 487863 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[141 (1561521519200305152)]} 0 0
[junit4] 2> 487865 INFO (qtp452615839-6278) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[142 (1561521519202402304)]} 0 0
[junit4] 2> 487871 INFO (qtp816044000-6293) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[142 (1561521519209742336)]} 0 0
[junit4] 2> 487872 INFO (qtp452615839-6278) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[143 (1561521519210790912)]} 0 0
[junit4] 2> 487873 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[143 (1561521519211839488)]} 0 0
[junit4] 2> 487874 INFO (qtp452615839-6278) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[144 (1561521519211839488)]} 0 0
[junit4] 2> 487874 INFO (qtp816044000-6295) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[144 (1561521519212888064)]} 0 0
[junit4] 2> 487875 INFO (qtp452615839-6278) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[145 (1561521519213936640)]} 0 0
[junit4] 2> 487878 INFO (qtp816044000-6295) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[145 (1561521519216033792)]} 0 0
[junit4] 2> 487879 INFO (qtp452615839-6276) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[146 (1561521519217082368)]} 0 0
[junit4] 2> 487880 INFO (qtp816044000-6294) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[146 (1561521519218130944)]} 0 0
[junit4] 2> 487892 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[147 (1561521519230713856)]} 0 0
[junit4] 2> 487893 INFO (qtp816044000-6294) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[147 (1561521519231762432)]} 0 0
[junit4] 2> 487894 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[148 (1561521519232811008)]} 0 0
[junit4] 2> 487894 INFO (qtp816044000-6294) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[148 (1561521519233859584)]} 0 0
[junit4] 2> 487895 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[149 (1561521519234908160)]} 0 0
[junit4] 2> 487896 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={wt=javabin&version=2}{add=[149 (1561521519234908160)]} 0 0
[junit4] 2> 487896 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 487896 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@26e8d515
[junit4] 2> 487953 INFO (qtp452615839-6271) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@347700bc[collection1] main]
[junit4] 2> 487954 INFO (searcherExecutor-3275-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@347700bc[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C9) Uninverting(_1(7.0.0):C59)))}
[junit4] 2> 487954 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 487954 INFO (qtp452615839-6271) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 58
[junit4] 2> 487955 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 487955 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@2a2e1756
[junit4] 2> 488002 INFO (qtp816044000-6291) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6d31c867[collection1] main]
[junit4] 2> 488003 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 488004 INFO (searcherExecutor-3286-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@6d31c867[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.0.0):C9) Uninverting(_1(7.0.0):C59)))}
[junit4] 2> 488005 INFO (qtp816044000-6291) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/tl/v path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 49
[junit4] 2> 488006 INFO (qtp452615839-6278) [ x:collection1] o.a.s.h.RequestHandlerBase Ignoring exception matching parameter cannot be negative
[junit4] 2> 488006 INFO (qtp452615839-6278) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*&distrib=false&start=-1&wt=javabin&version=2} status=400 QTime=0
[junit4] 2> 488007 INFO (qtp452615839-6276) [ x:collection1] o.a.s.h.RequestHandlerBase Ignoring exception matching parameter cannot be negative
[junit4] 2> 488007 INFO (qtp452615839-6276) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*&distrib=false&start=0&rows=-1&wt=javabin&version=2} status=400 QTime=0
[junit4] 2> 488009 INFO (qtp452615839-6276) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_ti1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488070 INFO (qtp816044000-6289) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_ti1+desc&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::083]:33332/tl/v|[ff01::213]:33332/tl/v|[ff01::114]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967537&isShard=true&wt=javabin} hits=68 status=0 QTime=17
[junit4] 2> 488074 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967537&ids=11,121,111,114,104,137,127,116,138,149&isShard=true&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::083]:33332/tl/v|[ff01::213]:33332/tl/v|[ff01::114]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488086 INFO (qtp816044000-6291) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=http://127.0.0.1:54981/tl/v/collection1|[ff01::083]:33332/tl/v|[ff01::213]:33332/tl/v|[ff01::114]:33332/tl/v&sort=n_ti1+desc&wt=javabin&version=2} hits=68 status=0 QTime=64
[junit4] 2> 488089 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_ti1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488091 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_ti1+asc&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v|[ff01::114]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967605&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488097 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967605&ids=101,145,146,3,16,117,129,107,109,130&isShard=true&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v|[ff01::114]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488098 INFO (qtp816044000-6295) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v|[ff01::114]:33332/tl/v&sort=n_ti1+asc&wt=javabin&version=2} hits=68 status=0 QTime=7
[junit4] 2> 488100 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_f1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488326 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_f1+desc&shard.url=[ff01::114]:33332/tl/v|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&rows=10&version=2&q=*:*&NOW=1489182967617&isShard=true&wt=javabin} hits=68 status=0 QTime=1
[junit4] 2> 488329 INFO (qtp816044000-6291) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967617&ids=143,132,102,114,147,115,138,149,8,108&isShard=true&shard.url=[ff01::114]:33332/tl/v|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488335 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::114]:33332/tl/v|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&sort=n_f1+desc&wt=javabin&version=2} hits=68 status=0 QTime=232
[junit4] 2> 488338 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_f1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488343 INFO (qtp816044000-6292) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_f1+asc&shard.url=[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v|[ff01::213]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967857&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488345 INFO (qtp816044000-6292) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967857&ids=133,124,3,17,139,106,117,7,129,118&isShard=true&shard.url=[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v|[ff01::213]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488354 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v|[ff01::213]:33332/tl/v&sort=n_f1+asc&wt=javabin&version=2} hits=68 status=0 QTime=12
[junit4] 2> 488358 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_tf1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488364 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tf1+desc&shard.url=[ff01::083]:33332/tl/v|[ff01::114]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&rows=10&version=2&q=*:*&NOW=1489182967877&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488365 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967877&ids=122,101,16,138,127,149,1001,139,141,130&isShard=true&shard.url=[ff01::083]:33332/tl/v|[ff01::114]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488370 INFO (qtp816044000-6289) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::083]:33332/tl/v|[ff01::114]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&sort=n_tf1+desc&wt=javabin&version=2} hits=68 status=0 QTime=7
[junit4] 2> 488371 INFO (qtp452615839-6274) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_tf1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488373 INFO (qtp816044000-6295) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tf1+asc&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v|[ff01::213]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967887&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488374 INFO (qtp816044000-6295) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967887&ids=1,12,2,114,136,106,7,118,8,109&isShard=true&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v|[ff01::213]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488375 INFO (qtp816044000-6291) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v|[ff01::213]:33332/tl/v&sort=n_tf1+asc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 488377 INFO (qtp452615839-6274) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_d1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488378 INFO (qtp816044000-6295) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_d1+desc&shard.url=[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::083]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967893&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488379 INFO (qtp816044000-6295) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967893&ids=11,111,13,14,135,103,126,129,120,142&isShard=true&shard.url=[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::083]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488380 INFO (qtp816044000-6291) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::083]:33332/tl/v&sort=n_d1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 488385 INFO (qtp452615839-6274) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_d1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488388 INFO (qtp816044000-6289) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_d1+asc&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967901&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488391 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967901&ids=144,101,112,116,1001,106,128,8,119,9&isShard=true&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488394 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v&sort=n_d1+asc&wt=javabin&version=2} hits=68 status=0 QTime=7
[junit4] 2> 488396 INFO (qtp452615839-6274) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_td1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488401 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_td1+desc&shard.url=http://127.0.0.1:54981/tl/v/collection1&rows=10&version=2&q=*:*&NOW=1489182967913&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488408 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967913&ids=132,133,1,3,146,15,148,149,117,8&isShard=true&shard.url=http://127.0.0.1:54981/tl/v/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488410 INFO (qtp816044000-6292) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=http://127.0.0.1:54981/tl/v/collection1&sort=n_td1+desc&wt=javabin&version=2} hits=68 status=0 QTime=12
[junit4] 2> 488414 INFO (qtp452615839-6274) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_td1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488415 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_td1+asc&shard.url=http://127.0.0.1:54981/tl/v/collection1&rows=10&version=2&q=*:*&NOW=1489182967930&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488416 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967930&ids=143,110,12,13,135,103,104,5,138,6&isShard=true&shard.url=http://127.0.0.1:54981/tl/v/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488417 INFO (qtp816044000-6295) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=http://127.0.0.1:54981/tl/v/collection1&sort=n_td1+asc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 488419 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_l1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488420 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_l1+desc&shard.url=http://127.0.0.1:54981/tl/v/collection1&rows=10&version=2&q=*:*&NOW=1489182967935&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488421 INFO (qtp816044000-6292) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967935&ids=110,1,101,3,124,147,15,148,115,104&isShard=true&shard.url=http://127.0.0.1:54981/tl/v/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488422 INFO (qtp816044000-6289) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=http://127.0.0.1:54981/tl/v/collection1&sort=n_l1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 488423 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_l1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488429 INFO (qtp816044000-6292) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_l1+asc&shard.url=[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::114]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967939&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488430 INFO (qtp816044000-6295) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967939&ids=143,11,146,14,103,5,116,105,119,130&isShard=true&shard.url=[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::114]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488431 INFO (qtp816044000-6291) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::114]:33332/tl/v&sort=n_l1+asc&wt=javabin&version=2} hits=68 status=0 QTime=6
[junit4] 2> 488432 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_tl1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488434 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tl1+desc&shard.url=[ff01::083]:33332/tl/v|[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967948&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488435 INFO (qtp816044000-6289) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967948&ids=11,100,146,14,115,116,17,106,117,130&isShard=true&shard.url=[ff01::083]:33332/tl/v|[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488436 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::083]:33332/tl/v|[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&sort=n_tl1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 488437 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_tl1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488441 INFO (qtp816044000-6292) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tl1+asc&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967953&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488442 INFO (qtp816044000-6291) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967953&ids=122,12,103,147,16,104,148,126,128,118&isShard=true&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488443 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&sort=n_tl1+asc&wt=javabin&version=2} hits=68 status=0 QTime=5
[junit4] 2> 488444 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_dt1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488446 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_dt1+desc&shard.url=[ff01::114]:33332/tl/v|[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&rows=10&version=2&q=*:*&NOW=1489182967960&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488447 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967960&ids=133,144,1,122,145,124,103,137,117,141&isShard=true&shard.url=[ff01::114]:33332/tl/v|[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488448 INFO (qtp816044000-6295) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::114]:33332/tl/v|[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&sort=n_dt1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 488449 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_dt1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488452 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_dt1+asc&shard.url=[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967965&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488454 INFO (qtp816044000-6291) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967965&ids=143,135,125,114,115,126,107,129,119,108&isShard=true&shard.url=[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488455 INFO (qtp816044000-6289) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&sort=n_dt1+asc&wt=javabin&version=2} hits=68 status=0 QTime=4
[junit4] 2> 488458 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_tdt1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488460 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tdt1+desc&shard.url=[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&rows=10&version=2&q=*:*&NOW=1489182967974&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488461 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967974&ids=143,133,2,146,14,16,148,105,1001,130&isShard=true&shard.url=[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488462 INFO (qtp816044000-6292) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::083]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&sort=n_tdt1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 488463 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=n_tdt1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488464 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tdt1+asc&shard.url=[ff01::114]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967979&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488465 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967979&ids=12,145,3,114,17,7,106,8,119,9&isShard=true&shard.url=[ff01::114]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488466 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::114]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::213]:33332/tl/v|[ff01::083]:33332/tl/v&sort=n_tdt1+asc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 488467 INFO (qtp452615839-6275) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=a_i1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488469 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=a_i1+desc&shard.url=[ff01::083]:33332/tl/v|[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967983&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488470 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967983&ids=1,12,2,13,3,5,7,8,9,10&isShard=true&shard.url=[ff01::083]:33332/tl/v|[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488471 INFO (qtp816044000-6291) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::083]:33332/tl/v|[ff01::213]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&sort=a_i1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 488472 INFO (qtp452615839-6271) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort={!func}testfunc(add(a_i1,5))+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488474 INFO (qtp816044000-6288) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort={!func}testfunc(add(a_i1,5))+desc&shard.url=[ff01::083]:33332/tl/v|[ff01::114]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&rows=10&version=2&q=*:*&NOW=1489182967988&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488475 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&shards.purpose=64&NOW=1489182967988&ids=1,12,2,13,3,5,7,8,9,10&isShard=true&shard.url=[ff01::083]:33332/tl/v|[ff01::114]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488476 INFO (qtp816044000-6294) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&shards=[ff01::083]:33332/tl/v|[ff01::114]:33332/tl/v|http://127.0.0.1:54981/tl/v/collection1&sort={!func}testfunc(add(a_i1,5))+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 488477 INFO (qtp452615839-6271) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=a_i1[*+TO+*]&distrib=false&sort=a_i1+asc&wt=javabin&version=2} hits=13 status=0 QTime=0
[junit4] 2> 488479 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=a_i1+asc&shard.url=http://127.0.0.1:54981/tl/v/collection1&rows=10&version=2&q=a_i1[*+TO+*]&NOW=1489182967993&isShard=true&wt=javabin} hits=13 status=0 QTime=0
[junit4] 2> 488480 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=a_i1[*+TO+*]&distrib=false&shards.purpose=64&NOW=1489182967993&ids=11,12,1,13,2,3,4,6,7,9&isShard=true&shard.url=http://127.0.0.1:54981/tl/v/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 488481 INFO (qtp816044000-6295) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=a_i1[*+TO+*]&shards=http://127.0.0.1:54981/tl/v/collection1&sort=a_i1+asc&wt=javabin&version=2} hits=13 status=0 QTime=2
[junit4] 2> 488482 INFO (qtp452615839-6271) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={q=*:*&distrib=false&sort=a_i1+asc,+id+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 488484 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=a_i1+asc,+id+desc&shard.url=http://127.0.0.1:54981/tl/v/collection1|[ff01::114]:33332/tl/v&rows=10&version=2&q=*:*&NOW=1489182967998&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 488485 INFO (qtp816044000-6293) [ x:collection1] o.a.s.c.S.Request [collection1] webap
[...truncated too long message...]
12-6332) [ x:collection1] o.a.s.h.c.SearchHandler Query: distrib=false&fl=id&group.limit=10&shards.purpose=4&start=0&sort=a_i1+asc,+id+asc&shards.info=true&shard.url=[ff01::114]:33332/tl/v|http://127.0.0.1:56765/tl/v/collection1&rows=100&group.query=a_t:kings+OR+a_t:eggs&version=2&group.distributed.second=true&q=*:*&shards.tolerant=true&NOW=1489183012397&isShard=true&timeAllowed=1&wt=javabin&group=true; The request took too long to iterate over terms. Timeout: timeoutAt: 27559257609589810 (System.nanoTime(): 27559257610385933), TermsEnum=org.apache.lucene.codecs.blocktree.SegmentTermsEnum@26c298f8
[junit4] 2> 532887 INFO (qtp221240912-6332) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={distrib=false&fl=id&group.limit=10&shards.purpose=4&start=0&sort=a_i1+asc,+id+asc&shards.info=true&shard.url=[ff01::114]:33332/tl/v|http://127.0.0.1:56765/tl/v/collection1&rows=100&group.query=a_t:kings+OR+a_t:eggs&version=2&group.distributed.second=true&q=*:*&shards.tolerant=true&NOW=1489183012397&isShard=true&timeAllowed=1&wt=javabin&group=true} status=0 QTime=2
[junit4] 2> 532895 INFO (qtp221240912-6335) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/tl/v path=/select params={fl=id,a_i1&group.limit=10&sort=a_i1+asc,+id+asc&shards.info=true&rows=100&group.query=a_t:kings+OR+a_t:eggs&version=2&q=*:*&shards=[ff01::114]:33332/tl/v|http://127.0.0.1:56765/tl/v/collection1,[ff01::213]:33332/tl/v|http://127.0.0.1:53747/tl/v/collection1&shards.tolerant=true&timeAllowed=1&wt=javabin&group=true} status=0 QTime=12
[junit4] 2> 532897 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.SolrTestCaseJ4 ###Ending test
[junit4] 2> 532898 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@30a3f52c{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 532898 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=585404784
[junit4] 2> 532898 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 532908 INFO (coreCloseExecutor-3328-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@74be2588
[junit4] 2> 532952 INFO (coreCloseExecutor-3328-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=1958618504
[junit4] 2> 532952 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@50034561{/tl/v,null,UNAVAILABLE}
[junit4] 2> 532993 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@72df59e2{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 532994 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1021558519
[junit4] 2> 532994 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 533009 INFO (coreCloseExecutor-3330-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@14d4e9ad
[junit4] 2> 533027 INFO (coreCloseExecutor-3330-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=349497773
[junit4] 2> 533028 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@34bcc138{/tl/v,null,UNAVAILABLE}
[junit4] 2> 533037 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@61a7c863{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 533037 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=105273754
[junit4] 2> 533042 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 533053 INFO (coreCloseExecutor-3332-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@1ae8d861
[junit4] 2> 533063 INFO (coreCloseExecutor-3332-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=451467361
[junit4] 2> 533065 INFO (TEST-TestDistributedSearch.test-seed#[F77419D33FBE9D05]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@3aeaaa3c{/tl/v,null,UNAVAILABLE}
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestDistributedSearch -Dtests.method=test -Dtests.seed=F77419D33FBE9D05 -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=en-ZA -Dtests.timezone=America/Kentucky/Monticello -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] FAILURE 47.5s J0 | TestDistributedSearch.test <<<
[junit4] > Throwable #1: java.lang.AssertionError: Expected to find shardAddress in the up shard info: {error=org.apache.solr.client.solrj.SolrServerException: No live SolrServers available to handle this request,trace=org.apache.solr.client.solrj.SolrServerException: No live SolrServers available to handle this request
[junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:416)
[junit4] > at org.apache.solr.handler.component.HttpShardHandlerFactory.makeLoadBalancedRequest(HttpShardHandlerFactory.java:259)
[junit4] > at org.apache.solr.handler.component.HttpShardHandler.lambda$submit$0(HttpShardHandler.java:166)
[junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] > at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] > at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
[junit4] > at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] > ,time=2}
[junit4] > at __randomizedtesting.SeedInfo.seed([F77419D33FBE9D05:7F2026099142F0FD]:0)
[junit4] > at org.apache.solr.TestDistributedSearch.comparePartialResponses(TestDistributedSearch.java:1186)
[junit4] > at org.apache.solr.TestDistributedSearch.queryPartialResults(TestDistributedSearch.java:1127)
[junit4] > at org.apache.solr.TestDistributedSearch.test(TestDistributedSearch.java:987)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsRepeatStatement.callStatement(BaseDistributedSearchTestCase.java:1011)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:960)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 533068 INFO (SUITE-TestDistributedSearch-seed#[F77419D33FBE9D05]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-master/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_F77419D33FBE9D05-001
[junit4] 2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarity(queryNorm=false): {}, locale=en-ZA, timezone=America/Kentucky/Monticello
[junit4] 2> NOTE: Linux 3.13.0-85-generic amd64/Oracle Corporation 1.8.0_121 (64-bit)/cpus=4,threads=1,free=129599136,total=531628032
[junit4] 2> NOTE: All tests run in this JVM: [TestSizeLimitedDistributedMap, TestAnalyzedSuggestions, TestCollapseQParserPlugin, TestTestInjection, TestDelegationWithHadoopAuth, QueryEqualityTest, ConfigSetsAPITest, TestManagedSynonymFilterFactory, TestMinMaxOnMultiValuedField, TestSolrCoreProperties, BasicAuthStandaloneTest, ScriptEngineTest, TestBadConfig, CurrencyFieldOpenExchangeTest, HdfsLockFactoryTest, TestClusterStateMutator, TestConfigSets, TestSimpleQParserPlugin, TestLMJelinekMercerSimilarityFactory, CoreSorterTest, FastVectorHighlighterTest, PathHierarchyTokenizerFactoryTest, TestJettySolrRunner, RequiredFieldsTest, CustomCollectionTest, TestSolrDeletionPolicy2, TestDownShardTolerantSearch, TestCoreAdminApis, LeaderElectionIntegrationTest, TestSolrQueryParserResource, TlogReplayBufferedWhileIndexingTest, SolrCloudReportersTest, TestRandomCollapseQParserPlugin, CollectionReloadTest, SimpleMLTQParserTest, DeleteNodeTest, TestSolrConfigHandlerCloud, ResponseLogComponentTest, BaseCdcrDistributedZkTest, SignatureUpdateProcessorFactoryTest, ReplaceNodeTest, ChangedSchemaMergeTest, HttpSolrCallGetCoreTest, TestScoreJoinQPScore, TemplateUpdateProcessorTest, TestDefaultStatsCache, RegexBoostProcessorTest, TestCloudInspectUtil, RankQueryTest, TestRandomFaceting, TestGeoJSONResponseWriter, TestSolrQueryResponse, TestRealTimeGet, TestLazyCores, TestFieldCacheReopen, TestExactStatsCache, BJQParserTest, TestUseDocValuesAsStored, CloneFieldUpdateProcessorFactoryTest, TestReplicaProperties, ReturnFieldsTest, TestDFRSimilarityFactory, TestBinaryResponseWriter, TestRestoreCore, MinimalSchemaTest, TestManagedSchema, CacheHeaderTest, TestDistributedSearch]
[junit4] Completed [180/695 (1!)] on J0 in 47.47s, 1 test, 1 failure <<< FAILURES!
[...truncated 64291 lines...]