You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2018/08/12 17:11:48 UTC
[JENKINS] Lucene-Solr-7.x-Linux (64bit/jdk-10) - Build # 2541 -
Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Linux/2541/
Java: 64bit/jdk-10 -XX:-UseCompressedOops -XX:+UseParallelGC
1 tests failed.
FAILED: org.apache.solr.cloud.hdfs.HDFSCollectionsAPITest.testDataDirIsNotReused
Error Message:
null Live Nodes: [127.0.0.1:39627_solr, 127.0.0.1:45033_solr] Last available state: DocCollection(test//collections/test/state.json/5)={ "pullReplicas":"0", "replicationFactor":"1", "shards":{"shard1":{ "range":"80000000-7fffffff", "state":"active", "replicas":{"core_node2":{ "dataDir":"hdfs://localhost.localdomain:46007/data/test/core_node2/data/", "base_url":"https://127.0.0.1:39627/solr", "node_name":"127.0.0.1:39627_solr", "type":"NRT", "force_set_state":"false", "ulogDir":"hdfs://localhost.localdomain:46007/data/test/core_node2/data/tlog", "core":"test_shard1_replica_n1", "shared_storage":"true", "state":"down", "leader":"true"}}}}, "router":{"name":"compositeId"}, "maxShardsPerNode":"1", "autoAddReplicas":"false", "nrtReplicas":"1", "tlogReplicas":"0"}
Stack Trace:
java.lang.AssertionError:
null
Live Nodes: [127.0.0.1:39627_solr, 127.0.0.1:45033_solr]
Last available state: DocCollection(test//collections/test/state.json/5)={
"pullReplicas":"0",
"replicationFactor":"1",
"shards":{"shard1":{
"range":"80000000-7fffffff",
"state":"active",
"replicas":{"core_node2":{
"dataDir":"hdfs://localhost.localdomain:46007/data/test/core_node2/data/",
"base_url":"https://127.0.0.1:39627/solr",
"node_name":"127.0.0.1:39627_solr",
"type":"NRT",
"force_set_state":"false",
"ulogDir":"hdfs://localhost.localdomain:46007/data/test/core_node2/data/tlog",
"core":"test_shard1_replica_n1",
"shared_storage":"true",
"state":"down",
"leader":"true"}}}},
"router":{"name":"compositeId"},
"maxShardsPerNode":"1",
"autoAddReplicas":"false",
"nrtReplicas":"1",
"tlogReplicas":"0"}
at __randomizedtesting.SeedInfo.seed([49AE1EEF878F286C:51B15C9B94D68ACB]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.SolrCloudTestCase.waitForState(SolrCloudTestCase.java:280)
at org.apache.solr.cloud.hdfs.HDFSCollectionsAPITest.testDataDirIsNotReused(HDFSCollectionsAPITest.java:90)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at 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.base/java.lang.Thread.run(Thread.java:844)
Build Log:
[...truncated 14513 lines...]
[junit4] Suite: org.apache.solr.cloud.hdfs.HDFSCollectionsAPITest
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/init-core-data-001
[junit4] 2> 1695867 WARN (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=30 numCloses=30
[junit4] 2> 1695867 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true
[junit4] 2> 1695867 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason="", ssl=0.0/0.0, value=0.0/0.0, clientAuth=0.0/0.0)
[junit4] 2> 1695868 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> 1695868 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-001
[junit4] 2> 1695868 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1695868 INFO (Thread-5795) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1695868 INFO (Thread-5795) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1695870 ERROR (Thread-5795) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 1695968 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:34639
[junit4] 2> 1695970 INFO (zkConnectionManagerCallback-5493-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1695973 INFO (jetty-launcher-5490-thread-2) [ ] o.e.j.s.Server jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 10+46
[junit4] 2> 1695973 INFO (jetty-launcher-5490-thread-1) [ ] o.e.j.s.Server jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 10+46
[junit4] 2> 1695974 INFO (jetty-launcher-5490-thread-2) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1695974 INFO (jetty-launcher-5490-thread-2) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1695974 INFO (jetty-launcher-5490-thread-2) [ ] o.e.j.s.session node0 Scavenging every 660000ms
[junit4] 2> 1695974 INFO (jetty-launcher-5490-thread-1) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1695974 INFO (jetty-launcher-5490-thread-1) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1695974 INFO (jetty-launcher-5490-thread-1) [ ] o.e.j.s.session node0 Scavenging every 660000ms
[junit4] 2> 1695974 INFO (jetty-launcher-5490-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@5bfc3b62{/solr,null,AVAILABLE}
[junit4] 2> 1695974 INFO (jetty-launcher-5490-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@51864363{/solr,null,AVAILABLE}
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@2fd538ea{SSL,[ssl, http/1.1]}{127.0.0.1:45033}
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@7b053d59{SSL,[ssl, http/1.1]}{127.0.0.1:39627}
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-1) [ ] o.e.j.s.Server Started @1696005ms
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-2) [ ] o.e.j.s.Server Started @1696005ms
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=45033}
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=39627}
[junit4] 2> 1695975 ERROR (jetty-launcher-5490-thread-2) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1695975 ERROR (jetty-launcher-5490-thread-1) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-2) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-1) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.5.0
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.5.0
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-08-12T16:50:14.525585Z
[junit4] 2> 1695975 INFO (jetty-launcher-5490-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-08-12T16:50:14.525592Z
[junit4] 2> 1695976 INFO (zkConnectionManagerCallback-5497-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1695976 INFO (zkConnectionManagerCallback-5496-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1695976 INFO (jetty-launcher-5490-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1695976 INFO (jetty-launcher-5490-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1696005 INFO (jetty-launcher-5490-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34639/solr
[junit4] 2> 1696006 INFO (zkConnectionManagerCallback-5501-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1696007 INFO (zkConnectionManagerCallback-5503-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1696039 INFO (jetty-launcher-5490-thread-2) [n:127.0.0.1:39627_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:39627_solr
[junit4] 2> 1696039 INFO (jetty-launcher-5490-thread-2) [n:127.0.0.1:39627_solr ] o.a.s.c.Overseer Overseer (id=72149010157535236-127.0.0.1:39627_solr-n_0000000000) starting
[junit4] 2> 1696042 INFO (zkConnectionManagerCallback-5510-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1696043 INFO (jetty-launcher-5490-thread-2) [n:127.0.0.1:39627_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:34639/solr ready
[junit4] 2> 1696043 INFO (OverseerStateUpdate-72149010157535236-127.0.0.1:39627_solr-n_0000000000) [ ] o.a.s.c.Overseer Starting to work on the main queue : 127.0.0.1:39627_solr
[junit4] 2> 1696043 INFO (jetty-launcher-5490-thread-2) [n:127.0.0.1:39627_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39627_solr
[junit4] 2> 1696044 INFO (zkCallback-5509-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1696044 INFO (zkCallback-5502-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1696056 INFO (jetty-launcher-5490-thread-2) [n:127.0.0.1:39627_solr ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 1696065 INFO (jetty-launcher-5490-thread-2) [n:127.0.0.1:39627_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_39627.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1696069 INFO (jetty-launcher-5490-thread-2) [n:127.0.0.1:39627_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_39627.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1696069 INFO (jetty-launcher-5490-thread-2) [n:127.0.0.1:39627_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_39627.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1696070 INFO (jetty-launcher-5490-thread-2) [n:127.0.0.1:39627_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-001/node2/.
[junit4] 2> 1696081 INFO (jetty-launcher-5490-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34639/solr
[junit4] 2> 1696081 INFO (zkConnectionManagerCallback-5515-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1696082 INFO (zkConnectionManagerCallback-5517-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1696085 INFO (jetty-launcher-5490-thread-1) [n:127.0.0.1:45033_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1696087 INFO (jetty-launcher-5490-thread-1) [n:127.0.0.1:45033_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 1696087 INFO (jetty-launcher-5490-thread-1) [n:127.0.0.1:45033_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45033_solr
[junit4] 2> 1696087 INFO (zkCallback-5509-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1696087 INFO (zkCallback-5502-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1696087 INFO (zkCallback-5516-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1696095 INFO (zkConnectionManagerCallback-5524-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1696095 INFO (jetty-launcher-5490-thread-1) [n:127.0.0.1:45033_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1696096 INFO (jetty-launcher-5490-thread-1) [n:127.0.0.1:45033_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:34639/solr ready
[junit4] 2> 1696096 INFO (jetty-launcher-5490-thread-1) [n:127.0.0.1:45033_solr ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 1696104 INFO (jetty-launcher-5490-thread-1) [n:127.0.0.1:45033_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_45033.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1696108 INFO (jetty-launcher-5490-thread-1) [n:127.0.0.1:45033_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_45033.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1696108 INFO (jetty-launcher-5490-thread-1) [n:127.0.0.1:45033_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_45033.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1696109 INFO (jetty-launcher-5490-thread-1) [n:127.0.0.1:45033_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-001/node1/.
[junit4] 2> 1696120 INFO (zkConnectionManagerCallback-5527-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 1> Formatting using clusterid: testClusterID
[junit4] 2> 1696341 WARN (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.h.m.i.MetricsConfig Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
[junit4] 2> 1696347 WARN (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 1696348 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 1696350 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log Extract jar:file:/home/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.4-tests.jar!/webapps/hdfs to ./temp/Jetty_localhost_localdomain_41763_hdfs____f7l10x/webapp
[junit4] 2> 1696416 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost.localdomain:41763
[junit4] 2> 1696762 WARN (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 1696763 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 1696766 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log Extract jar:file:/home/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.4-tests.jar!/webapps/datanode to ./temp/Jetty_localhost_46727_datanode____fa9zoh/webapp
[junit4] 2> 1696840 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:46727
[junit4] 2> 1696863 WARN (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 1696863 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 1696875 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log Extract jar:file:/home/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.4-tests.jar!/webapps/datanode to ./temp/Jetty_localhost_45847_datanode____vxstq9/webapp
[junit4] 2> 1696947 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:45847
[junit4] 2> 1697906 ERROR (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-002/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-002/hdfsBaseDir/data/data2/]] heartbeating to localhost.localdomain/127.0.0.1:46007) [ ] o.a.h.h.s.d.DirectoryScanner dfs.datanode.directoryscan.throttle.limit.ms.per.sec set to value below 1 ms/sec. Assuming default value of 1000
[junit4] 2> 1697912 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x4f4a7c639c0f0: from storage DS-90138403-a0e2-4927-a27e-56ef79163abd node DatanodeRegistration(127.0.0.1:39107, datanodeUuid=adc37b17-6f23-43f5-a6b2-2c5fe596b10c, infoPort=33515, infoSecurePort=0, ipcPort=36227, storageInfo=lv=-56;cid=testClusterID;nsid=734541958;c=0), blocks: 0, hasStaleStorage: true, processing time: 0 msecs
[junit4] 2> 1697912 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x4f4a7c639c0f0: from storage DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c node DatanodeRegistration(127.0.0.1:39107, datanodeUuid=adc37b17-6f23-43f5-a6b2-2c5fe596b10c, infoPort=33515, infoSecurePort=0, ipcPort=36227, storageInfo=lv=-56;cid=testClusterID;nsid=734541958;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
[junit4] 2> 1698000 ERROR (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-002/hdfsBaseDir/data/data3/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-002/hdfsBaseDir/data/data4/]] heartbeating to localhost.localdomain/127.0.0.1:46007) [ ] o.a.h.h.s.d.DirectoryScanner dfs.datanode.directoryscan.throttle.limit.ms.per.sec set to value below 1 ms/sec. Assuming default value of 1000
[junit4] 2> 1698003 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x4f4a7cba9dddd: from storage DS-b3d60b09-23b3-4f58-b703-8878b84cefc1 node DatanodeRegistration(127.0.0.1:43997, datanodeUuid=77fc7342-9c20-49cf-8b17-e835704d9e44, infoPort=42407, infoSecurePort=0, ipcPort=43283, storageInfo=lv=-56;cid=testClusterID;nsid=734541958;c=0), blocks: 0, hasStaleStorage: true, processing time: 0 msecs
[junit4] 2> 1698003 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x4f4a7cba9dddd: from storage DS-c3612df8-9684-4ded-bae6-d69cf1b8074c node DatanodeRegistration(127.0.0.1:43997, datanodeUuid=77fc7342-9c20-49cf-8b17-e835704d9e44, infoPort=42407, infoSecurePort=0, ipcPort=43283, storageInfo=lv=-56;cid=testClusterID;nsid=734541958;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
[junit4] 2> 1698076 INFO (zkConnectionManagerCallback-5532-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1698077 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1698078 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:34639/solr ready
[junit4] 2> 1698101 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDataDirIsNotReused
[junit4] 2> 1698111 INFO (qtp744664744-22413) [n:127.0.0.1:45033_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params collection.configName=conf1&name=test&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=127.0.0.1:39627_solr&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 1698112 INFO (OverseerThreadFactory-9082-thread-1) [ ] o.a.s.c.a.c.CreateCollectionCmd Create collection test
[junit4] 2> 1698216 INFO (OverseerStateUpdate-72149010157535236-127.0.0.1:39627_solr-n_0000000000) [ ] o.a.s.c.o.SliceMutator createReplica() {
[junit4] 2> "operation":"ADDREPLICA",
[junit4] 2> "collection":"test",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"test_shard1_replica_n1",
[junit4] 2> "state":"down",
[junit4] 2> "base_url":"https://127.0.0.1:39627/solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "waitForFinalState":"false"}
[junit4] 2> 1698427 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr x:test_shard1_replica_n1] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf1&newCollection=true&name=test_shard1_replica_n1&action=CREATE&numShards=1&collection=test&shard=shard1&wt=javabin&version=2&replicaType=NRT
[junit4] 2> 1698427 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr x:test_shard1_replica_n1] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 1699433 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.5.0
[junit4] 2> 1699437 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.IndexSchema [test_shard1_replica_n1] Schema name=minimal
[junit4] 2> 1699438 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 1699438 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.CoreContainer Creating SolrCore 'test_shard1_replica_n1' using configuration from collection test, trusted=true
[junit4] 2> 1699438 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_39627.solr.core.test.shard1.replica_n1' (registry 'solr.core.test.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1699438 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://localhost.localdomain:46007/data
[junit4] 2> 1699438 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 1699438 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 1699438 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SolrCore [[test_shard1_replica_n1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-001/node2/test_shard1_replica_n1], dataDir=[hdfs://localhost.localdomain:46007/data/test/core_node2/data/]
[junit4] 2> 1699439 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost.localdomain:46007/data/test/core_node2/data/snapshot_metadata
[junit4] 2> 1699447 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost.localdomain:46007/data/test/core_node2/data
[junit4] 2> 1699457 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost.localdomain:46007/data/test/core_node2/data/index
[junit4] 2> 1699476 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741825_1001{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|FINALIZED]]} size 0
[junit4] 2> 1699478 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741825_1001 size 69
[junit4] 2> 1699519 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
[junit4] 2> 1699519 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1699519 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=3
[junit4] 2> 1699525 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1699525 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1699532 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@7bb4e9e3[test_shard1_replica_n1] main]
[junit4] 2> 1699533 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1699533 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1699533 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 1699534 INFO (searcherExecutor-9094-thread-1-processing-n:127.0.0.1:39627_solr x:test_shard1_replica_n1 c:test s:shard1 r:core_node2) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SolrCore [test_shard1_replica_n1] Registered new searcher Searcher@7bb4e9e3[test_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1699534 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1608612701100048384
[junit4] 2> 1699536 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.ZkShardTerms Successful update of terms at /collections/test/terms/shard1 to Terms{values={core_node2=0}, version=0}
[junit4] 2> 1699538 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1699538 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1699538 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:39627/solr/test_shard1_replica_n1/
[junit4] 2> 1699538 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1699538 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SyncStrategy https://127.0.0.1:39627/solr/test_shard1_replica_n1/ has no replicas
[junit4] 2> 1699538 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 1699539 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:39627/solr/test_shard1_replica_n1/ shard1
[junit4] 2> 1699640 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1699641 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf1&newCollection=true&name=test_shard1_replica_n1&action=CREATE&numShards=1&collection=test&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1214
[junit4] 2> 1699643 INFO (qtp744664744-22413) [n:127.0.0.1:45033_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> 1699742 INFO (zkCallback-5502-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/test/state.json] for collection [test] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1700113 INFO (OverseerCollectionConfigSetProcessor-72149010157535236-127.0.0.1:39627_solr-n_0000000000) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 1700643 INFO (qtp744664744-22413) [n:127.0.0.1:45033_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={collection.configName=conf1&name=test&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=127.0.0.1:39627_solr&wt=javabin&version=2} status=0 QTime=2532
[junit4] 2> 1700650 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.ZkShardTerms Successful update of terms at /collections/test/terms/shard1 to Terms{values={core_node2=1}, version=1}
[junit4] 2> 1700655 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [test_shard1_replica_n1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[1 (1608612702267113472)]} 0 7
[junit4] 2> 1700657 INFO (qtp1421548405-22416) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [test_shard1_replica_n1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[2 (1608612702276550656)]} 0 1
[junit4] 2> 1700658 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1608612702278647808,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1700658 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@3f422601 commitCommandVersion:1608612702278647808
[junit4] 2> 1700666 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741827_1003{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|RBW]]} size 0
[junit4] 2> 1700666 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741827_1003{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|RBW]]} size 0
[junit4] 2> 1700671 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741828_1004{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW]]} size 0
[junit4] 2> 1700672 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741828_1004 size 529
[junit4] 2> 1700676 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741829_1005{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW], ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|FINALIZED]]} size 0
[junit4] 2> 1700678 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741829_1005 size 182
[junit4] 2> 1700682 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741830_1006{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW]]} size 0
[junit4] 2> 1700683 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741830_1006{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW]]} size 0
[junit4] 2> 1700687 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741831_1007{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|RBW]]} size 0
[junit4] 2> 1700687 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741831_1007 size 59
[junit4] 2> 1700692 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741832_1008{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW]]} size 0
[junit4] 2> 1700692 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741832_1008 size 83
[junit4] 2> 1700697 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741833_1009{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|RBW], ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|FINALIZED]]} size 0
[junit4] 2> 1700697 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741833_1009{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|RBW], ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|FINALIZED]]} size 0
[junit4] 2> 1700702 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741834_1010{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW], ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|FINALIZED]]} size 0
[junit4] 2> 1700702 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741834_1010{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW], ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|FINALIZED]]} size 0
[junit4] 2> 1700707 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741835_1011{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|FINALIZED]]} size 0
[junit4] 2> 1700707 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741835_1011 size 85
[junit4] 2> 1700711 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741836_1012{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|FINALIZED]]} size 0
[junit4] 2> 1700711 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741836_1012{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|FINALIZED], ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|FINALIZED]]} size 0
[junit4] 2> 1700716 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741837_1013{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|RBW], ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW]]} size 0
[junit4] 2> 1700717 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741837_1013 size 69
[junit4] 2> 1700721 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741838_1014{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW], ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|RBW]]} size 0
[junit4] 2> 1700721 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741838_1014{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW], ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|RBW]]} size 0
[junit4] 2> 1700726 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741839_1015{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|RBW]]} size 0
[junit4] 2> 1700726 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741839_1015 size 100
[junit4] 2> 1700731 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741840_1016{UCState=COMMITTED, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW], ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|RBW]]} size 101
[junit4] 2> 1700731 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741840_1016 size 101
[junit4] 2> 1701137 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741841_1017{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW], ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|FINALIZED]]} size 0
[junit4] 2> 1701138 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741841_1017{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|FINALIZED], ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|FINALIZED]]} size 0
[junit4] 2> 1701163 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@7d6b1259[test_shard1_replica_n1] main]
[junit4] 2> 1701164 INFO (searcherExecutor-9094-thread-1-processing-n:127.0.0.1:39627_solr x:test_shard1_replica_n1 c:test s:shard1 r:core_node2) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SolrCore [test_shard1_replica_n1] Registered new searcher Searcher@7d6b1259[test_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.5.0):C2)))}
[junit4] 2> 1701166 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741826_1002{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW]]} size 75
[junit4] 2> 1701166 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741826_1002{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-c3612df8-9684-4ded-bae6-d69cf1b8074c:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW]]} size 75
[junit4] 2> 1701166 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1701166 INFO (qtp1421548405-22412) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [test_shard1_replica_n1] webapp=/solr path=/update params={_stateVer_=test:4&waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 508
[junit4] 2> 1701172 INFO (qtp1421548405-22416) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [test_shard1_replica_n1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[3 (1608612702812372992)]} 0 5
[junit4] 2> 1701173 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@7b053d59{SSL,[ssl, http/1.1]}{127.0.0.1:0}
[junit4] 2> 1701173 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1529312291
[junit4] 2> 1701173 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1701173 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@988cf06: rootName = solr_39627, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@6c7fa772
[junit4] 2> 1701178 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 1701178 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@7d3c574c: rootName = solr_39627, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@39c64054
[junit4] 2> 1701180 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1701180 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@38a08ea1: rootName = solr_39627, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@7cc4d908
[junit4] 2> 1701181 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:39627_solr
[junit4] 2> 1701182 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 1701182 INFO (zkCallback-5531-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1701182 INFO (zkCallback-5523-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1701182 INFO (zkCallback-5516-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1701182 INFO (zkCallback-5502-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1701182 INFO (zkCallback-5509-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1701182 INFO (coreCloseExecutor-9099-thread-1) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SolrCore [test_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@17197aa0
[junit4] 2> 1701182 INFO (coreCloseExecutor-9099-thread-1) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.test.shard1.replica_n1, tag=17197aa0
[junit4] 2> 1701182 INFO (coreCloseExecutor-9099-thread-1) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@70ae0c6a: rootName = solr_39627, domain = solr.core.test.shard1.replica_n1, service url = null, agent id = null] for registry solr.core.test.shard1.replica_n1 / com.codahale.metrics.MetricRegistry@7b3cfbd9
[junit4] 2> 1701187 INFO (coreCloseExecutor-9099-thread-1) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.test.shard1.leader, tag=17197aa0
[junit4] 2> 1701191 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741842_1018{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-90138403-a0e2-4927-a27e-56ef79163abd:NORMAL:127.0.0.1:39107|RBW]]} size 75
[junit4] 2> 1701191 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741842_1018 size 75
[junit4] 2> 1701192 INFO (coreCloseExecutor-9099-thread-1) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.h.HdfsDirectory Closing hdfs directory hdfs://localhost.localdomain:46007/data/test/core_node2/data
[junit4] 2> 1701192 INFO (coreCloseExecutor-9099-thread-1) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.h.HdfsDirectory Closing hdfs directory hdfs://localhost.localdomain:46007/data/test/core_node2/data/index
[junit4] 2> 1701192 INFO (coreCloseExecutor-9099-thread-1) [n:127.0.0.1:39627_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.h.HdfsDirectory Closing hdfs directory hdfs://localhost.localdomain:46007/data/test/core_node2/data/snapshot_metadata
[junit4] 2> 1701193 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.c.Overseer Overseer (id=72149010157535236-127.0.0.1:39627_solr-n_0000000000) closing
[junit4] 2> 1701193 INFO (OverseerStateUpdate-72149010157535236-127.0.0.1:39627_solr-n_0000000000) [ ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:39627_solr
[junit4] 2> 1701192 ERROR (OldIndexDirectoryCleanupThreadForCore-test_shard1_replica_n1) [ ] o.a.s.c.HdfsDirectoryFactory Error checking for old index directories to clean-up.
[junit4] 2> java.io.IOException: Filesystem closed
[junit4] 2> at org.apache.hadoop.hdfs.DFSClient.checkOpen(DFSClient.java:808) ~[hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.hdfs.DFSClient.listPaths(DFSClient.java:2083) ~[hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.hdfs.DFSClient.listPaths(DFSClient.java:2069) ~[hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.hdfs.DistributedFileSystem.listStatusInternal(DistributedFileSystem.java:791) ~[hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.hdfs.DistributedFileSystem.access$700(DistributedFileSystem.java:106) ~[hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.hdfs.DistributedFileSystem$18.doCall(DistributedFileSystem.java:853) ~[hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.hdfs.DistributedFileSystem$18.doCall(DistributedFileSystem.java:849) ~[hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.fs.FileSystemLinkResolver.resolve(FileSystemLinkResolver.java:81) ~[hadoop-common-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.hdfs.DistributedFileSystem.listStatus(DistributedFileSystem.java:860) ~[hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.fs.FileSystem.listStatus(FileSystem.java:1517) ~[hadoop-common-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.fs.FileSystem.listStatus(FileSystem.java:1557) ~[hadoop-common-2.7.4.jar:?]
[junit4] 2> at org.apache.solr.core.HdfsDirectoryFactory.cleanupOldIndexDirectories(HdfsDirectoryFactory.java:528) [java/:?]
[junit4] 2> at org.apache.solr.core.SolrCore.lambda$cleanupOldIndexDirectories$21(SolrCore.java:3099) [java/:?]
[junit4] 2> at java.lang.Thread.run(Thread.java:844) [?:?]
[junit4] 2> 1701193 WARN (OverseerAutoScalingTriggerThread-72149010157535236-127.0.0.1:39627_solr-n_0000000000) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 1701195 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@51864363{/solr,null,UNAVAILABLE}
[junit4] 2> 1701195 INFO (zkCallback-5516-thread-1) [ ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:45033_solr
[junit4] 2> 1701195 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.e.j.s.session node0 Stopped scavenging
[junit4] 2> 1701198 INFO (zkCallback-5516-thread-1) [ ] o.a.s.c.Overseer Overseer (id=72149010157535239-127.0.0.1:45033_solr-n_0000000001) starting
[junit4] 2> 1701200 INFO (OverseerStateUpdate-72149010157535239-127.0.0.1:45033_solr-n_0000000001) [ ] o.a.s.c.Overseer Starting to work on the main queue : 127.0.0.1:45033_solr
[junit4] 2> 1701201 INFO (zkCallback-5531-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/test/state.json] for collection [test] has occurred - updating... (live nodes size: [1])
[junit4] 2> 1701201 INFO (zkCallback-5531-thread-2) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/test/state.json] for collection [test] has occurred - updating... (live nodes size: [1])
[junit4] 2> 1701201 INFO (qtp744664744-22415) [n:127.0.0.1:45033_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :delete with params name=test&action=DELETE&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 1701202 INFO (OverseerThreadFactory-9104-thread-1) [ ] o.a.s.c.a.c.OverseerCollectionMessageHandler Executing Collection Cmd=action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true&deleteMetricsHistory=true, asyncId=null
[junit4] 2> 1701910 INFO (qtp744664744-22415) [n:127.0.0.1:45033_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=test&action=DELETE&wt=javabin&version=2} status=0 QTime=708
[junit4] 2> 1701911 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.e.j.s.Server jetty-9.4.11.v20180605; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 10+46
[junit4] 2> 1701911 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1701911 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1701911 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.e.j.s.session node0 Scavenging every 600000ms
[junit4] 2> 1701911 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2eb79c87{/solr,null,AVAILABLE}
[junit4] 2> 1701912 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@b5890c6{SSL,[ssl, http/1.1]}{127.0.0.1:39627}
[junit4] 2> 1701912 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.e.j.s.Server Started @1701941ms
[junit4] 2> 1701912 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=39627}
[junit4] 2> 1701912 ERROR (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1701912 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 1701912 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.5.0
[junit4] 2> 1701912 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1701912 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1701912 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-08-12T16:50:20.462325Z
[junit4] 2> 1701913 INFO (zkConnectionManagerCallback-5534-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1701913 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1701949 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34639/solr
[junit4] 2> 1701949 INFO (zkConnectionManagerCallback-5538-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1701950 INFO (zkConnectionManagerCallback-5540-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1701953 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1701955 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 1701955 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:39627_solr
[junit4] 2> 1701955 INFO (zkCallback-5531-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1701956 INFO (zkCallback-5523-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1701956 INFO (zkCallback-5516-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1701958 INFO (zkCallback-5539-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1701968 INFO (zkConnectionManagerCallback-5547-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1701969 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1701969 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:34639/solr ready
[junit4] 2> 1701969 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 1701984 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_39627.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1701992 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_39627.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1701992 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_39627.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1701994 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-001/node2/.
[junit4] 2> 1701994 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [n:127.0.0.1:39627_solr ] o.a.s.c.CorePropertiesLocator Cores are: [test_shard1_replica_n1]
[junit4] 2> 1703203 INFO (OverseerCollectionConfigSetProcessor-72149010157535239-127.0.0.1:45033_solr-n_0000000001) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000002 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 1711996 ERROR (coreContainerWorkExecutor-9106-thread-1-processing-n:127.0.0.1:39627_solr) [n:127.0.0.1:39627_solr ] o.a.s.c.CoreContainer Error waiting for SolrCore to be loaded on startup
[junit4] 2> org.apache.solr.cloud.ZkController$NotInClusterStateException: coreNodeName core_node2 does not exist in shard shard1, ignore the exception if the replica was deleted
[junit4] 2> at org.apache.solr.cloud.ZkController.checkStateInZk(ZkController.java:1811) ~[java/:?]
[junit4] 2> at org.apache.solr.cloud.ZkController.preRegister(ZkController.java:1710) ~[java/:?]
[junit4] 2> at org.apache.solr.core.CoreContainer.createFromDescriptor(CoreContainer.java:1131) ~[java/:?]
[junit4] 2> at org.apache.solr.core.CoreContainer.lambda$load$13(CoreContainer.java:684) ~[java/:?]
[junit4] 2> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedCallable.call(InstrumentedExecutorService.java:197) ~[metrics-core-3.2.6.jar:3.2.6]
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:209) [java/:?]
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135) [?:?]
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
[junit4] 2> at java.lang.Thread.run(Thread.java:844) [?:?]
[junit4] 2> 1712006 INFO (qtp1909712226-22813) [n:127.0.0.1:39627_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params collection.configName=conf1&name=test&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=127.0.0.1:45033_solr&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 1712007 INFO (OverseerThreadFactory-9104-thread-2) [ ] o.a.s.c.a.c.CreateCollectionCmd Create collection test
[junit4] 2> 1712110 INFO (OverseerStateUpdate-72149010157535239-127.0.0.1:45033_solr-n_0000000001) [ ] o.a.s.c.o.SliceMutator createReplica() {
[junit4] 2> "operation":"ADDREPLICA",
[junit4] 2> "collection":"test",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"test_shard1_replica_n3",
[junit4] 2> "state":"down",
[junit4] 2> "base_url":"https://127.0.0.1:45033/solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "waitForFinalState":"false"}
[junit4] 2> 1712314 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr x:test_shard1_replica_n3] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node4&collection.configName=conf1&newCollection=true&name=test_shard1_replica_n3&action=CREATE&numShards=1&collection=test&shard=shard1&wt=javabin&version=2&replicaType=NRT
[junit4] 2> 1713318 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.5.0
[junit4] 2> 1713322 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.s.IndexSchema [test_shard1_replica_n3] Schema name=minimal
[junit4] 2> 1713322 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 1713322 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.CoreContainer Creating SolrCore 'test_shard1_replica_n3' using configuration from collection test, trusted=true
[junit4] 2> 1713323 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_45033.solr.core.test.shard1.replica_n3' (registry 'solr.core.test.shard1.replica_n3') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@6036f092
[junit4] 2> 1713323 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://localhost.localdomain:46007/data
[junit4] 2> 1713323 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 1713323 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 1713323 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SolrCore [[test_shard1_replica_n3] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-001/node1/test_shard1_replica_n3], dataDir=[hdfs://localhost.localdomain:46007/data/test/core_node4/data/]
[junit4] 2> 1713324 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost.localdomain:46007/data/test/core_node4/data/snapshot_metadata
[junit4] 2> 1713332 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost.localdomain:46007/data/test/core_node4/data
[junit4] 2> 1713345 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost.localdomain:46007/data/test/core_node4/data/index
[junit4] 2> 1713361 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:39107 is added to blk_1073741843_1019{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|FINALIZED]]} size 0
[junit4] 2> 1713361 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:43997 is added to blk_1073741843_1019{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-b3d60b09-23b3-4f58-b703-8878b84cefc1:NORMAL:127.0.0.1:43997|RBW], ReplicaUC[[DISK]DS-ae228920-aa8c-42c4-a8b0-5ba25f95944c:NORMAL:127.0.0.1:39107|FINALIZED]]} size 0
[junit4] 2> 1713396 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
[junit4] 2> 1713396 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1713396 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=3
[junit4] 2> 1713402 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1713402 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1713412 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.s.SolrIndexSearcher Opening [Searcher@6943eed2[test_shard1_replica_n3] main]
[junit4] 2> 1713413 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 1713413 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 1713413 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 1713414 INFO (searcherExecutor-9114-thread-1-processing-n:127.0.0.1:45033_solr x:test_shard1_replica_n3 c:test s:shard1 r:core_node4) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SolrCore [test_shard1_replica_n3] Registered new searcher Searcher@6943eed2[test_shard1_replica_n3] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1713414 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1608612715654283264
[junit4] 2> 1713417 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.ZkShardTerms Successful update of terms at /collections/test/terms/shard1 to Terms{values={core_node4=0}, version=0}
[junit4] 2> 1713418 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 1713418 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 1713418 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:45033/solr/test_shard1_replica_n3/
[junit4] 2> 1713418 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 1713419 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SyncStrategy https://127.0.0.1:45033/solr/test_shard1_replica_n3/ has no replicas
[junit4] 2> 1713419 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 1713420 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:45033/solr/test_shard1_replica_n3/ shard1
[junit4] 2> 1713521 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 1713522 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node4&collection.configName=conf1&newCollection=true&name=test_shard1_replica_n3&action=CREATE&numShards=1&collection=test&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1208
[junit4] 2> 1713524 INFO (qtp1909712226-22813) [n:127.0.0.1:39627_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> 1713622 INFO (zkCallback-5516-thread-1) [ ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/test/state.json] for collection [test] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1714008 INFO (OverseerCollectionConfigSetProcessor-72149010157535239-127.0.0.1:45033_solr-n_0000000001) [ ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000004 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 1714524 INFO (qtp1909712226-22813) [n:127.0.0.1:39627_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={collection.configName=conf1&name=test&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=127.0.0.1:45033_solr&wt=javabin&version=2} status=0 QTime=2518
[junit4] 2> 1756102 INFO (qtp744664744-22417) [n:127.0.0.1:45033_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.core.test.shard1.replica_n3:INDEX.sizeInBytes&key=solr.core.test.shard1.replica_n3:QUERY./select.requests&key=solr.core.test.shard1.replica_n3:UPDATE./update.requests} status=0 QTime=3
[junit4] 2> 1756104 INFO (qtp744664744-22843) [n:127.0.0.1:45033_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=1
[junit4] 2> 1756107 INFO (qtp1909712226-22813) [n:127.0.0.1:39627_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/metrics params={wt=javabin&version=2&key=solr.jvm:os.processCpuLoad&key=solr.node:CONTAINER.fs.coreRoot.usableSpace&key=solr.jvm:os.systemLoadAverage&key=solr.jvm:memory.heap.used} status=0 QTime=0
[junit4] 2> 1804526 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[49AE1EEF878F286C]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDataDirIsNotReused
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=HDFSCollectionsAPITest -Dtests.method=testDataDirIsNotReused -Dtests.seed=49AE1EEF878F286C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=zh -Dtests.timezone=America/Kentucky/Louisville -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] FAILURE 106s J2 | HDFSCollectionsAPITest.testDataDirIsNotReused <<<
[junit4] > Throwable #1: java.lang.AssertionError:
[junit4] > null
[junit4] > Live Nodes: [127.0.0.1:39627_solr, 127.0.0.1:45033_solr]
[junit4] > Last available state: DocCollection(test//collections/test/state.json/5)={
[junit4] > "pullReplicas":"0",
[junit4] > "replicationFactor":"1",
[junit4] > "shards":{"shard1":{
[junit4] > "range":"80000000-7fffffff",
[junit4] > "state":"active",
[junit4] > "replicas":{"core_node2":{
[junit4] > "dataDir":"hdfs://localhost.localdomain:46007/data/test/core_node2/data/",
[junit4] > "base_url":"https://127.0.0.1:39627/solr",
[junit4] > "node_name":"127.0.0.1:39627_solr",
[junit4] > "type":"NRT",
[junit4] > "force_set_state":"false",
[junit4] > "ulogDir":"hdfs://localhost.localdomain:46007/data/test/core_node2/data/tlog",
[junit4] > "core":"test_shard1_replica_n1",
[junit4] > "shared_storage":"true",
[junit4] > "state":"down",
[junit4] > "leader":"true"}}}},
[junit4] > "router":{"name":"compositeId"},
[junit4] > "maxShardsPerNode":"1",
[junit4] > "autoAddReplicas":"false",
[junit4] > "nrtReplicas":"1",
[junit4] > "tlogReplicas":"0"}
[junit4] > at __randomizedtesting.SeedInfo.seed([49AE1EEF878F286C:51B15C9B94D68ACB]:0)
[junit4] > at org.apache.solr.cloud.SolrCloudTestCase.waitForState(SolrCloudTestCase.java:280)
[junit4] > at org.apache.solr.cloud.hdfs.HDFSCollectionsAPITest.testDataDirIsNotReused(HDFSCollectionsAPITest.java:90)
[junit4] > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4] > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[junit4] > at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4] > at java.base/java.lang.reflect.Method.invoke(Method.java:564)
[junit4] > at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> 1804528 INFO (jetty-closer-5491-thread-2) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@2fd538ea{SSL,[ssl, http/1.1]}{127.0.0.1:0}
[junit4] 2> 1804528 INFO (jetty-closer-5491-thread-2) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1225070275
[junit4] 2> 1804528 INFO (jetty-closer-5491-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@b5890c6{SSL,[ssl, http/1.1]}{127.0.0.1:39627}
[junit4] 2> 1804529 INFO (jetty-closer-5491-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1804529 INFO (jetty-closer-5491-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@718746db: rootName = solr_45033, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@6f94dfe8
[junit4] 2> 1804529 INFO (jetty-closer-5491-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=199801851
[junit4] 2> 1804529 INFO (jetty-closer-5491-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1804529 INFO (jetty-closer-5491-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@5081ae52: rootName = solr_39627, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@3174f469
[junit4] 2> 1804535 INFO (jetty-closer-5491-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 1804535 INFO (jetty-closer-5491-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@780261b: rootName = solr_45033, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@39c64054
[junit4] 2> 1804535 INFO (jetty-closer-5491-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 1804535 INFO (jetty-closer-5491-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@753fa20b: rootName = solr_39627, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@39c64054
[junit4] 2> 1804537 INFO (jetty-closer-5491-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1804537 INFO (jetty-closer-5491-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@64f9132e: rootName = solr_39627, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@7cc4d908
[junit4] 2> 1804538 INFO (jetty-closer-5491-thread-1) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:39627_solr
[junit4] 2> 1804538 INFO (jetty-closer-5491-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1804538 INFO (jetty-closer-5491-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1e11e6f8: rootName = solr_45033, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@7cc4d908
[junit4] 2> 1804539 INFO (zkCallback-5516-thread-3) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1804539 INFO (zkCallback-5546-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1804539 INFO (zkCallback-5539-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1804539 INFO (zkCallback-5523-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1804540 INFO (jetty-closer-5491-thread-2) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:45033_solr
[junit4] 2> 1804541 INFO (zkCallback-5523-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0)
[junit4] 2> 1804541 INFO (jetty-closer-5491-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 1804541 INFO (zkCallback-5546-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0)
[junit4] 2> 1
[...truncated too long message...]
portManager interrupted
[junit4] 2> 1804614 WARN (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-002/hdfsBaseDir/data/data3/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-002/hdfsBaseDir/data/data4/]] heartbeating to localhost.localdomain/127.0.0.1:46007) [ ] o.a.h.h.s.d.DataNode Ending block pool service for: Block pool BP-273712441-88.99.242.108-1534092614680 (Datanode Uuid 77fc7342-9c20-49cf-8b17-e835704d9e44) service to localhost.localdomain/127.0.0.1:46007
[junit4] 2> 1804615 WARN (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.h.h.s.d.DirectoryScanner DirectoryScanner: shutdown has been called
[junit4] 2> 1804628 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:0
[junit4] 2> 1804628 WARN (594364498@qtp-691691302-1 - Acceptor0 HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:46727) [ ] o.a.h.h.HttpServer2 HttpServer Acceptor: isRunning is false. Rechecking.
[junit4] 2> 1804628 WARN (594364498@qtp-691691302-1 - Acceptor0 HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:46727) [ ] o.a.h.h.HttpServer2 HttpServer Acceptor: isRunning is false
[junit4] 2> 1804629 WARN (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-002/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-002/hdfsBaseDir/data/data2/]] heartbeating to localhost.localdomain/127.0.0.1:46007) [ ] o.a.h.h.s.d.IncrementalBlockReportManager IncrementalBlockReportManager interrupted
[junit4] 2> 1804629 WARN (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-002/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001/tempDir-002/hdfsBaseDir/data/data2/]] heartbeating to localhost.localdomain/127.0.0.1:46007) [ ] o.a.h.h.s.d.DataNode Ending block pool service for: Block pool BP-273712441-88.99.242.108-1534092614680 (Datanode Uuid adc37b17-6f23-43f5-a6b2-2c5fe596b10c) service to localhost.localdomain/127.0.0.1:46007
[junit4] 2> 1804640 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.m.log Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@localhost.localdomain:0
[junit4] 2> 1804753 INFO (SUITE-HDFSCollectionsAPITest-seed#[49AE1EEF878F286C]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:34639 34639
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J2/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_49AE1EEF878F286C-001
[junit4] 2> Aug 12, 2018 4:52:03 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 66 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {id=PostingsFormat(name=LuceneFixedGap)}, docValues:{_version_=DocValuesFormat(name=Direct)}, maxPointsInLeafNode=19, maxMBSortInHeap=5.144988771086968, sim=RandomSimilarity(queryNorm=true): {}, locale=zh, timezone=America/Kentucky/Louisville
[junit4] 2> NOTE: Linux 4.15.0-29-generic amd64/Oracle Corporation 10 (64-bit)/cpus=8,threads=2,free=187780192,total=522190848
[junit4] 2> NOTE: All tests run in this JVM: [TestHdfsCloudBackupRestore, CloudMLTQParserTest, BasicZkTest, SliceStateTest, TestTolerantUpdateProcessorCloud, TestDistribDocBasedVersion, TermVectorComponentTest, TestQueryTypes, TestDocBasedVersionConstraints, TestMultiWordSynonyms, PeerSyncWithIndexFingerprintCachingTest, TestFilteredDocIdSet, SOLR749Test, TestDistributedGrouping, SoftAutoCommitTest, DistributedIntervalFacetingTest, TestScoreJoinQPNoScore, SpatialHeatmapFacetsTest, TestSolrCloudWithKerberosAlt, WordBreakSolrSpellCheckerTest, TestNRTOpen, HttpPartitionTest, TestConfigsApi, BitVectorTest, ZkCLITest, TestClusterStateProvider, HdfsChaosMonkeyNothingIsSafeTest, TestBinaryResponseWriter, MetricTriggerIntegrationTest, MetricsConfigTest, CustomCollectionTest, ChaosMonkeySafeLeaderTest, TestStressUserVersions, AsyncCallRequestStatusResponseTest, AlternateDirectoryTest, TestFieldCacheReopen, UniqFieldsUpdateProcessorFactoryTest, DistributedQueryComponentCustomSortTest, MetricsHistoryHandlerTest, TestPhraseSuggestions, DataDrivenBlockJoinTest, SearchRateTriggerTest, TestLegacyNumericRangeQueryBuilder, TestWithCollection, MoveReplicaHDFSTest, TestRandomCollapseQParserPlugin, SubstringBytesRefFilterTest, SystemInfoHandlerTest, CloneFieldUpdateProcessorFactoryTest, SolrXmlInZkTest, TestManagedStopFilterFactory, TestFunctionQuery, ImplicitSnitchTest, DistributedQueueTest, OverseerTest, RecoveryZkTest, TestDocumentBuilder, HdfsSyncSliceTest, OverriddenZkACLAndCredentialsProvidersTest, CacheHeaderTest, TestUnInvertedFieldException, TestNodeAddedTrigger, TestGeoJSONResponseWriter, DistributedSpellCheckComponentTest, ShufflingReplicaListTransformerTest, TestHalfAndHalfDocValues, V2StandaloneTest, TestSolrCloudSnapshots, TestPHPSerializedResponseWriter, HdfsUnloadDistributedZkTest, DistributedDebugComponentTest, SolrRrdBackendFactoryTest, TestComplexPhraseLeadingWildcard, TestWordDelimiterFilterFactory, TestDirectoryFactory, ZkNodePropsTest, TestSearchPerf, SimpleCollectionCreateDeleteTest, TestSystemIdResolver, ReplicaListTransformerTest, AdminHandlersProxyTest, TestBlobHandler, DocExpirationUpdateProcessorFactoryTest, LeaderFailoverAfterPartitionTest, SolrGraphiteReporterTest, TestLRUStatsCache, TestManagedSchemaThreadSafety, DirectoryFactoryTest, ConjunctionSolrSpellCheckerTest, TestNumericTerms32, TestJettySolrRunner, HLLSerializationTest, QueryEqualityTest, TestSolrConfigHandler, TestSSLRandomization, SegmentsInfoRequestHandlerTest, TestDynamicFieldCollectionResource, TestLegacyFieldReuse, CoreAdminHandlerTest, TestSubQueryTransformerDistrib, TestRestManager, TestFieldResource, MultiThreadedOCPTest, DeleteInactiveReplicaTest, TestInPlaceUpdatesDistrib, FastVectorHighlighterTest, AddBlockUpdateTest, FileUtilsTest, LeaderElectionContextKeyTest, TestCustomSort, TestIntervalFaceting, TestBackupRepositoryFactory, DistributedFacetPivotSmallTest, NoCacheHeaderTest, CoreMergeIndexesAdminHandlerTest, LukeRequestHandlerTest, TriLevelCompositeIdRoutingTest, TestSchemaVersionResource, TestFreeTextSuggestions, TestSchemaManager, TestClassicSimilarityFactory, BadComponentTest, SpellPossibilityIteratorTest, TestCloudPseudoReturnFields, CheckHdfsIndexTest, CleanupOldIndexTest, AddSchemaFieldsUpdateProcessorFactoryTest, AddReplicaTest, SolrMetricReporterTest, TestCloudSchemaless, TestConfigSetProperties, MigrateRouteKeyTest, TestInitQParser, AnalysisAfterCoreReloadTest, BasicFunctionalityTest, ConvertedLegacyTest, EchoParamsTest, MinimalSchemaTest, OutputWriterTest, SampleTest, SolrInfoBeanTest, SolrTestCaseJ4Test, TestGroupingSearch, TestHighlightDedupGrouping, TestJoin, TestRandomDVFaceting, TestSimpleTrackingShardHandler, TestSolrCoreProperties, TestTolerantSearch, TestTrie, PathHierarchyTokenizerFactoryTest, ProtectedTermFilterFactoryTest, TestCharFilters, TokenizerChainTest, TestLuceneIndexBackCompat, CollectionStateFormat2Test, ConcurrentCreateRoutedAliasTest, ConfigSetsAPITest, ConnectionManagerTest, DeleteLastCustomShardedReplicaTest, DeleteNodeTest, DeleteReplicaTest, LeaderTragicEventTest, ReplaceNodeNoTargetTest, ReplaceNodeTest, TestAuthenticationFramework, TestCloudConsistency, TestCloudRecovery, TestClusterProperties, TestConfigSetsAPI, TestLeaderInitiatedRecoveryThread, TestLockTree, TestMiniSolrCloudClusterSSL, TestPullReplicaErrorHandling, TestSegmentSorting, TestSolrCloudWithSecureImpersonation, ZkShardTermsTest, AssignTest, CollectionTooManyReplicasTest, ComputePlanActionTest, NodeAddedTriggerIntegrationTest, NodeLostTriggerIntegrationTest, NodeMarkersRegistrationTest, TestPolicyCloud, CdcrReplicationDistributedZkTest, CdcrReplicationHandlerTest, CdcrRequestHandlerTest, CdcrVersionReplicationTest, HDFSCollectionsAPITest]
[junit4] Completed [595/828 (1!)] on J2 in 118.97s, 1 test, 1 failure <<< FAILURES!
[...truncated 43116 lines...]
[repro] Jenkins log URL: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Linux/2541/consoleText
[repro] Revision: 6759ba7290304de397f7bcb7ad353feadcebacbb
[repro] Ant options: "-Dargs=-XX:-UseCompressedOops -XX:+UseParallelGC"
[repro] Repro line: ant test -Dtestcase=HDFSCollectionsAPITest -Dtests.method=testDataDirIsNotReused -Dtests.seed=49AE1EEF878F286C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=zh -Dtests.timezone=America/Kentucky/Louisville -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[repro] ant clean
[...truncated 6 lines...]
[repro] Test suites by module:
[repro] solr/core
[repro] HDFSCollectionsAPITest
[repro] ant compile-test
[...truncated 3413 lines...]
[repro] ant test-nocompile -Dtests.dups=5 -Dtests.maxfailures=5 -Dtests.class="*.HDFSCollectionsAPITest" -Dtests.showOutput=onerror "-Dargs=-XX:-UseCompressedOops -XX:+UseParallelGC" -Dtests.seed=49AE1EEF878F286C -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=zh -Dtests.timezone=America/Kentucky/Louisville -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[...truncated 76 lines...]
[repro] Failures:
[repro] 0/5 failed: org.apache.solr.cloud.hdfs.HDFSCollectionsAPITest
[repro] Exiting with code 0
[...truncated 40 lines...]