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/04/01 19:01:24 UTC
[JENKINS] Lucene-Solr-7.x-Linux (64bit/jdk-10) - Build # 1630 -
Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Linux/1630/
Java: 64bit/jdk-10 -XX:+UseCompressedOops -XX:+UseParallelGC
1 tests failed.
FAILED: org.apache.solr.TestDistributedSearch.test
Error Message:
Expected to find shardAddress in the up shard info: {error=org.apache.solr.client.solrj.SolrServerException: Time allowed to handle this request exceeded,trace=org.apache.solr.client.solrj.SolrServerException: Time allowed to handle this request exceeded at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:460) at org.apache.solr.handler.component.HttpShardHandlerFactory.makeLoadBalancedRequest(HttpShardHandlerFactory.java:273) at org.apache.solr.handler.component.HttpShardHandler.lambda$submit$0(HttpShardHandler.java:175) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176) at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:192) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:844) ,time=1}
Stack Trace:
java.lang.AssertionError: Expected to find shardAddress in the up shard info: {error=org.apache.solr.client.solrj.SolrServerException: Time allowed to handle this request exceeded,trace=org.apache.solr.client.solrj.SolrServerException: Time allowed to handle this request exceeded
at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:460)
at org.apache.solr.handler.component.HttpShardHandlerFactory.makeLoadBalancedRequest(HttpShardHandlerFactory.java:273)
at org.apache.solr.handler.component.HttpShardHandler.lambda$submit$0(HttpShardHandler.java:175)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:192)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:844)
,time=1}
at __randomizedtesting.SeedInfo.seed([B6D2ACC38739EB8B:3E86931929C58673]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.apache.solr.TestDistributedSearch.comparePartialResponses(TestDistributedSearch.java:1191)
at org.apache.solr.TestDistributedSearch.queryPartialResults(TestDistributedSearch.java:1132)
at org.apache.solr.TestDistributedSearch.test(TestDistributedSearch.java:992)
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 org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsRepeatStatement.callStatement(BaseDistributedSearchTestCase.java:1019)
at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:968)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at 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 1787 lines...]
[junit4] JVM J0: stdout was not empty, see: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/lucene/build/core/test/temp/junit4-J0-20180401_175406_03912851621630627701959.sysout
[junit4] >>> JVM J0 emitted unexpected output (verbatim) ----
[junit4] codec: FastDecompressionCompressingStoredFields, pf: TestBloomFilteredLucenePostings, dvf: Direct
[junit4] <<< JVM J0: EOF ----
[...truncated 11698 lines...]
[junit4] Suite: org.apache.solr.TestDistributedSearch
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/init-core-data-001
[junit4] 2> 987868 WARN (SUITE-TestDistributedSearch-seed#[B6D2ACC38739EB8B]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=2 numCloses=2
[junit4] 2> 987868 INFO (SUITE-TestDistributedSearch-seed#[B6D2ACC38739EB8B]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 987869 INFO (SUITE-TestDistributedSearch-seed#[B6D2ACC38739EB8B]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (false) via: @org.apache.solr.SolrTestCaseJ4$SuppressSSL(bugUrl="https://issues.apache.org/jira/browse/SOLR-9061")
[junit4] 2> 987869 INFO (SUITE-TestDistributedSearch-seed#[B6D2ACC38739EB8B]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> 987869 INFO (SUITE-TestDistributedSearch-seed#[B6D2ACC38739EB8B]-worker) [ ] o.a.s.BaseDistributedSearchTestCase Setting hostContext system property: /x_k/
[junit4] 2> 988052 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/tempDir-001/control/cores/collection1
[junit4] 2> 988053 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T14:27:37-07:00, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 988056 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 988056 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 988056 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.session Scavenging every 600000ms
[junit4] 2> 988057 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@4bcabfb5{/x_k,null,AVAILABLE}
[junit4] 2> 988058 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1ce1aff4{HTTP/1.1,[http/1.1]}{127.0.0.1:38959}
[junit4] 2> 988058 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.Server Started @988093ms
[junit4] 2> 988058 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/x_k, hostPort=38959, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/tempDir-001/control/cores}
[junit4] 2> 988058 ERROR (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 988058 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 988058 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.4.0
[junit4] 2> 988058 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 988059 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 988059 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-04-01T18:33:31.272027Z
[junit4] 2> 988059 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/tempDir-001/control/solr.xml
[junit4] 2> 988061 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored
[junit4] 2> 988061 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored
[junit4] 2> 988061 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@3e6d8b67, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 988089 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3e6d8b67
[junit4] 2> 988095 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3e6d8b67
[junit4] 2> 988095 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3e6d8b67
[junit4] 2> 988096 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/tempDir-001/control/cores
[junit4] 2> 988096 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 988100 INFO (coreLoadExecutor-4117-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 988101 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1/lib, /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 988122 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.4.0
[junit4] 2> 988140 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 988218 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 988225 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from configset /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1, trusted=true
[junit4] 2> 988225 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3e6d8b67
[junit4] 2> 988226 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 988226 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/tempDir-001/control/cores/collection1/data/]
[junit4] 2> 988227 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=13, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 988270 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 988270 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 988271 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 988271 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 988272 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=47, maxMergeAtOnceExplicit=12, maxMergedSegmentMB=2.78125, floorSegmentMB=1.2626953125, forceMergeDeletesPctAllowed=26.3633170003251, segmentsPerTier=45.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.7552200194934273
[junit4] 2> 988272 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@776649d5[collection1] main]
[junit4] 2> 988273 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 988313 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 988423 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 988423 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 988424 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 988424 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 988424 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 988424 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 988424 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 988425 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 988425 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 988425 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 988426 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@776649d5[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 988426 INFO (coreLoadExecutor-4117-thread-1) [ x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1596569798981976064
[junit4] 2> 989072 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.SolrTestCaseJ4 Writing core.properties file to /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/tempDir-001/shard0/cores/collection1
[junit4] 2> 989073 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-21T14:27:37-07:00, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 989081 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 989081 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 989081 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.session Scavenging every 660000ms
[junit4] 2> 989085 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@53f5b41d{/x_k,null,AVAILABLE}
[junit4] 2> 989085 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@30a1595e{HTTP/1.1,[http/1.1]}{127.0.0.1:41727}
[junit4] 2> 989085 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.Server Started @989120ms
[junit4] 2> 989085 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/x_k, hostPort=41727, coreRootDirectory=/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/tempDir-001/shard0/cores}
[junit4] 2> 989086 ERROR (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 989086 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 989086 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.4.0
[junit4] 2> 989086 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in standalone mode on port null
[junit4] 2> 989086 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 989086 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-04-01T18:33:32.299297Z
[junit4] 2> 989086 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.SolrXmlConfig Loading container configuration from /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/tempDir-001/shard0/solr.xml
[junit4] 2> 989088 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverWorkLoopDelay is ignored
[junit4] 2> 989088 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.SolrXmlConfig Configuration parameter autoReplicaFailoverBadNodeExpiration is ignored
[junit4] 2> 989089 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.SolrXmlConfig MBean server found: com.sun.jmx.mbeanserver.JmxMBeanServer@3e6d8b67, but no JMX reporters were configured - adding default JMX reporter.
[junit4] 2> 989125 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3e6d8b67
[junit4] 2> 989137 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3e6d8b67
[junit4] 2> 989137 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3e6d8b67
[junit4] 2> 989139 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/tempDir-001/shard0/cores
[junit4] 2> 989139 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.c.CorePropertiesLocator Cores are: [collection1]
[junit4] 2> 989139 INFO (coreLoadExecutor-4128-thread-1) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 989140 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1/lib, /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 989179 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.4.0
[junit4] 2> 989196 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 989273 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 989281 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from configset /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1, trusted=true
[junit4] 2> 989281 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@3e6d8b67
[junit4] 2> 989281 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 989281 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/core/src/test-files/solr/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001/tempDir-001/shard0/cores/collection1/data/]
[junit4] 2> 989283 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=13, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 989336 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 989336 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 989337 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 989337 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 989338 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=47, maxMergeAtOnceExplicit=12, maxMergedSegmentMB=2.78125, floorSegmentMB=1.2626953125, forceMergeDeletesPctAllowed=26.3633170003251, segmentsPerTier=45.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.7552200194934273
[junit4] 2> 989339 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@471bf2c6[collection1] main]
[junit4] 2> 989339 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 989359 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 989457 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 989458 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 989458 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 989458 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 989458 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 989458 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 989459 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 989459 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 989459 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 989460 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 989460 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@471bf2c6[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 989461 INFO (coreLoadExecutor-4128-thread-1) [ x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1596569800067252224
[junit4] 2> 989463 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.SolrTestCaseJ4 ###Starting test
[junit4] 2> 989469 INFO (qtp1421154257-18944) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{deleteByQuery=*:* (-1596569800071446528)} 0 4
[junit4] 2> 989484 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{deleteByQuery=*:* (-1596569800087175168)} 0 4
[junit4] 2> 989486 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[1 (1596569800091369472)]} 0 2
[junit4] 2> 989488 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[1 (1596569800094515200)]} 0 1
[junit4] 2> 989493 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[2 (1596569800095563776)]} 0 4
[junit4] 2> 989494 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[2 (1596569800101855232)]} 0 0
[junit4] 2> 989495 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[3 (1596569800102903808)]} 0 0
[junit4] 2> 989501 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[3 (1596569800108146688)]} 0 0
[junit4] 2> 989501 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[4 (1596569800109195264)]} 0 0
[junit4] 2> 989502 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[4 (1596569800109195264)]} 0 0
[junit4] 2> 989504 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[5 (1596569800112340992)]} 0 0
[junit4] 2> 989505 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[5 (1596569800113389568)]} 0 0
[junit4] 2> 989505 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[6 (1596569800113389568)]} 0 0
[junit4] 2> 989506 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[6 (1596569800113389569)]} 0 0
[junit4] 2> 989506 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[7 (1596569800114438144)]} 0 0
[junit4] 2> 989507 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[7 (1596569800114438144)]} 0 0
[junit4] 2> 989507 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[8 (1596569800115486720)]} 0 0
[junit4] 2> 989507 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[8 (1596569800115486720)]} 0 0
[junit4] 2> 989508 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[9 (1596569800116535296)]} 0 0
[junit4] 2> 989508 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[9 (1596569800116535296)]} 0 0
[junit4] 2> 989508 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1596569800116535297,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 989508 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@4002afd6 commitCommandVersion:1596569800116535297
[junit4] 2> 989532 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@48dc2d47[collection1] main]
[junit4] 2> 989534 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@48dc2d47[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.4.0):C9)))}
[junit4] 2> 989534 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 989534 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 26
[junit4] 2> 989535 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1596569800144846848,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 989535 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@63c849e6 commitCommandVersion:1596569800144846848
[junit4] 2> 989542 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@50b968f6[collection1] main]
[junit4] 2> 989544 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@50b968f6[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.4.0):C9)))}
[junit4] 2> 989544 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 989544 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 9
[junit4] 2> 989546 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[10 (1596569800155332608)]} 0 1
[junit4] 2> 989547 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[10 (1596569800156381184)]} 0 0
[junit4] 2> 989549 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[11 (1596569800158478336)]} 0 1
[junit4] 2> 989550 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[11 (1596569800160575488)]} 0 0
[junit4] 2> 989551 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[12 (1596569800161624064)]} 0 0
[junit4] 2> 989551 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[12 (1596569800161624064)]} 0 0
[junit4] 2> 989552 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[13 (1596569800161624065)]} 0 0
[junit4] 2> 989552 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[13 (1596569800162672640)]} 0 0
[junit4] 2> 989553 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[1001 (1596569800162672640)]} 0 0
[junit4] 2> 989553 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[1001 (1596569800163721216)]} 0 0
[junit4] 2> 989554 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[14 (1596569800164769792)]} 0 0
[junit4] 2> 989554 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[14 (1596569800164769792)]} 0 0
[junit4] 2> 989556 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[15 (1596569800166866944)]} 0 0
[junit4] 2> 989556 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[15 (1596569800166866944)]} 0 0
[junit4] 2> 989557 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[16 (1596569800167915520)]} 0 0
[junit4] 2> 989557 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[16 (1596569800167915520)]} 0 0
[junit4] 2> 989557 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[17 (1596569800167915521)]} 0 0
[junit4] 2> 989558 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[17 (1596569800168964096)]} 0 0
[junit4] 2> 989558 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[100 (1596569800168964096)]} 0 0
[junit4] 2> 989559 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[100 (1596569800170012672)]} 0 0
[junit4] 2> 989559 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[101 (1596569800170012672)]} 0 0
[junit4] 2> 989559 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[101 (1596569800170012673)]} 0 0
[junit4] 2> 989560 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[102 (1596569800170012673)]} 0 0
[junit4] 2> 989560 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[102 (1596569800171061248)]} 0 0
[junit4] 2> 989560 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[103 (1596569800171061248)]} 0 0
[junit4] 2> 989561 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[103 (1596569800172109824)]} 0 0
[junit4] 2> 989561 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[104 (1596569800172109824)]} 0 0
[junit4] 2> 989562 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[104 (1596569800172109825)]} 0 0
[junit4] 2> 989562 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[105 (1596569800173158400)]} 0 0
[junit4] 2> 989562 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[105 (1596569800173158400)]} 0 0
[junit4] 2> 989563 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[106 (1596569800173158401)]} 0 0
[junit4] 2> 989563 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[106 (1596569800174206976)]} 0 0
[junit4] 2> 989563 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[107 (1596569800174206976)]} 0 0
[junit4] 2> 989563 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[107 (1596569800174206977)]} 0 0
[junit4] 2> 989564 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[108 (1596569800175255552)]} 0 0
[junit4] 2> 989565 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[108 (1596569800175255552)]} 0 0
[junit4] 2> 989572 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[109 (1596569800183644160)]} 0 0
[junit4] 2> 989573 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[109 (1596569800184692736)]} 0 0
[junit4] 2> 989573 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[110 (1596569800184692736)]} 0 0
[junit4] 2> 989574 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[110 (1596569800184692737)]} 0 0
[junit4] 2> 989574 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[111 (1596569800185741312)]} 0 0
[junit4] 2> 989574 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[111 (1596569800185741312)]} 0 0
[junit4] 2> 989574 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[112 (1596569800185741313)]} 0 0
[junit4] 2> 989575 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[112 (1596569800185741313)]} 0 0
[junit4] 2> 989575 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[113 (1596569800186789888)]} 0 0
[junit4] 2> 989575 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[113 (1596569800186789888)]} 0 0
[junit4] 2> 989575 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[114 (1596569800186789889)]} 0 0
[junit4] 2> 989576 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[114 (1596569800187838464)]} 0 0
[junit4] 2> 989576 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[115 (1596569800187838464)]} 0 0
[junit4] 2> 989576 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[115 (1596569800187838465)]} 0 0
[junit4] 2> 989576 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[116 (1596569800187838465)]} 0 0
[junit4] 2> 989577 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[116 (1596569800188887040)]} 0 0
[junit4] 2> 989577 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[117 (1596569800188887040)]} 0 0
[junit4] 2> 989577 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[117 (1596569800188887041)]} 0 0
[junit4] 2> 989578 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[118 (1596569800188887041)]} 0 0
[junit4] 2> 989578 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[118 (1596569800189935616)]} 0 0
[junit4] 2> 989578 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[119 (1596569800189935616)]} 0 0
[junit4] 2> 989578 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[119 (1596569800189935617)]} 0 0
[junit4] 2> 989579 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[120 (1596569800190984192)]} 0 0
[junit4] 2> 989579 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[120 (1596569800190984192)]} 0 0
[junit4] 2> 989579 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[121 (1596569800190984193)]} 0 0
[junit4] 2> 989580 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[121 (1596569800192032768)]} 0 0
[junit4] 2> 989580 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[122 (1596569800192032768)]} 0 0
[junit4] 2> 989580 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[122 (1596569800192032769)]} 0 0
[junit4] 2> 989581 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[123 (1596569800193081344)]} 0 0
[junit4] 2> 989581 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[123 (1596569800193081344)]} 0 0
[junit4] 2> 989582 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[124 (1596569800194129920)]} 0 0
[junit4] 2> 989582 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[124 (1596569800194129920)]} 0 0
[junit4] 2> 989583 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[125 (1596569800194129921)]} 0 0
[junit4] 2> 989583 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[125 (1596569800195178496)]} 0 0
[junit4] 2> 989584 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[126 (1596569800195178496)]} 0 0
[junit4] 2> 989584 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[126 (1596569800196227072)]} 0 0
[junit4] 2> 989585 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[127 (1596569800196227072)]} 0 0
[junit4] 2> 989585 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[127 (1596569800197275648)]} 0 0
[junit4] 2> 989586 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[128 (1596569800197275648)]} 0 0
[junit4] 2> 989586 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[128 (1596569800198324224)]} 0 0
[junit4] 2> 989586 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[129 (1596569800198324224)]} 0 0
[junit4] 2> 989587 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[129 (1596569800199372800)]} 0 0
[junit4] 2> 989587 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[130 (1596569800199372800)]} 0 0
[junit4] 2> 989587 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[130 (1596569800199372801)]} 0 0
[junit4] 2> 989588 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[131 (1596569800200421376)]} 0 0
[junit4] 2> 989588 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[131 (1596569800200421376)]} 0 0
[junit4] 2> 989588 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[132 (1596569800200421377)]} 0 0
[junit4] 2> 989589 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[132 (1596569800201469952)]} 0 0
[junit4] 2> 989589 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[133 (1596569800201469952)]} 0 0
[junit4] 2> 989589 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[133 (1596569800201469953)]} 0 0
[junit4] 2> 989590 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[134 (1596569800201469953)]} 0 0
[junit4] 2> 989590 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[134 (1596569800202518528)]} 0 0
[junit4] 2> 989590 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[135 (1596569800202518528)]} 0 0
[junit4] 2> 989591 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[135 (1596569800202518529)]} 0 0
[junit4] 2> 989591 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[136 (1596569800203567104)]} 0 0
[junit4] 2> 989591 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[136 (1596569800203567104)]} 0 0
[junit4] 2> 989591 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[137 (1596569800203567105)]} 0 0
[junit4] 2> 989592 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[137 (1596569800204615680)]} 0 0
[junit4] 2> 989592 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[138 (1596569800204615680)]} 0 0
[junit4] 2> 989592 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[138 (1596569800204615681)]} 0 0
[junit4] 2> 989593 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[139 (1596569800205664256)]} 0 0
[junit4] 2> 989593 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[139 (1596569800205664256)]} 0 0
[junit4] 2> 989608 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[140 (1596569800221392896)]} 0 0
[junit4] 2> 989609 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[140 (1596569800222441472)]} 0 0
[junit4] 2> 989609 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[141 (1596569800222441472)]} 0 0
[junit4] 2> 989610 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[141 (1596569800223490048)]} 0 0
[junit4] 2> 989610 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[142 (1596569800223490048)]} 0 0
[junit4] 2> 989611 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[142 (1596569800224538624)]} 0 0
[junit4] 2> 989612 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[143 (1596569800225587200)]} 0 0
[junit4] 2> 989612 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[143 (1596569800225587200)]} 0 0
[junit4] 2> 989613 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[144 (1596569800226635776)]} 0 0
[junit4] 2> 989613 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[144 (1596569800226635776)]} 0 0
[junit4] 2> 989614 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[145 (1596569800227684352)]} 0 0
[junit4] 2> 989614 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[145 (1596569800227684352)]} 0 0
[junit4] 2> 989615 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[146 (1596569800228732928)]} 0 0
[junit4] 2> 989615 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[146 (1596569800228732928)]} 0 0
[junit4] 2> 989615 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[147 (1596569800228732929)]} 0 0
[junit4] 2> 989616 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[147 (1596569800229781504)]} 0 0
[junit4] 2> 989616 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[148 (1596569800229781504)]} 0 0
[junit4] 2> 989617 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[148 (1596569800229781505)]} 0 0
[junit4] 2> 989617 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[149 (1596569800230830080)]} 0 0
[junit4] 2> 989617 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={wt=javabin&version=2}{add=[149 (1596569800230830080)]} 0 0
[junit4] 2> 989618 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1596569800231878656,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 989618 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@4002afd6 commitCommandVersion:1596569800231878656
[junit4] 2> 989624 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@60d14ca9[collection1] main]
[junit4] 2> 989626 INFO (searcherExecutor-4118-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@60d14ca9[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.4.0):C9) Uninverting(_1(7.4.0):C59)))}
[junit4] 2> 989626 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 989626 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 8
[junit4] 2> 989627 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1596569800241315840,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 989627 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@63c849e6 commitCommandVersion:1596569800241315840
[junit4] 2> 989630 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@25b6e6f[collection1] main]
[junit4] 2> 989632 INFO (searcherExecutor-4129-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@25b6e6f[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.4.0):C9) Uninverting(_1(7.4.0):C59)))}
[junit4] 2> 989633 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 989633 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=/x_k path=/update params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2}{commit=} 0 6
[junit4] 2> 989633 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.h.RequestHandlerBase Ignoring exception matching parameter cannot be negative
[junit4] 2> 989633 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*&distrib=false&start=-1&wt=javabin&version=2} status=400 QTime=0
[junit4] 2> 989634 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.h.RequestHandlerBase Ignoring exception matching parameter cannot be negative
[junit4] 2> 989634 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*&distrib=false&start=0&rows=-1&wt=javabin&version=2} status=400 QTime=0
[junit4] 2> 989635 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_ti1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989640 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_ti1+desc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k|[ff01::083]:33332/x_k|[ff01::213]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612849&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989642 INFO (qtp1373384942-18962) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612849&ids=110,121,144,133,4,126,6,17,141,130&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k|[ff01::083]:33332/x_k|[ff01::213]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989644 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k|[ff01::083]:33332/x_k|[ff01::213]:33332/x_k&sort=n_ti1+desc&wt=javabin&version=2} hits=68 status=0 QTime=8
[junit4] 2> 989645 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_ti1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989647 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_ti1+asc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k|[ff01::213]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612859&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989648 INFO (qtp1373384942-18962) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612859&ids=1,123,2,112,124,114,104,109,10,120&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k|[ff01::213]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989649 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k|[ff01::213]:33332/x_k&sort=n_ti1+asc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 989650 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_f1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989652 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_f1+desc&shard.url=http://127.0.0.1:41727/x_k/collection1&rows=10&version=2&q=*:*&NOW=1522607612864&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989652 INFO (qtp1373384942-18962) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612864&ids=11,13,135,115,148,17,105,139,107,108&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989654 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1&sort=n_f1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 989654 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_f1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989674 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_f1+asc&shard.url=[ff01::213]:33332/x_k|[ff01::083]:33332/x_k|http://127.0.0.1:41727/x_k/collection1&rows=10&version=2&q=*:*&NOW=1522607612868&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989674 INFO (qtp1373384942-18962) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612868&ids=111,100,134,2,125,4,104,126,149,117&isShard=true&shard.url=[ff01::213]:33332/x_k|[ff01::083]:33332/x_k|http://127.0.0.1:41727/x_k/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989676 INFO (qtp1373384942-18967) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=[ff01::213]:33332/x_k|[ff01::083]:33332/x_k|http://127.0.0.1:41727/x_k/collection1&sort=n_f1+asc&wt=javabin&version=2} hits=68 status=0 QTime=20
[junit4] 2> 989677 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_tf1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989678 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tf1+desc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k|[ff01::213]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612890&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989678 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612890&ids=143,1,2,123,14,148,116,106,8,129&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k|[ff01::213]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989687 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k|[ff01::213]:33332/x_k&sort=n_tf1+desc&wt=javabin&version=2} hits=68 status=0 QTime=9
[junit4] 2> 989687 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_tf1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989688 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tf1+asc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612901&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989690 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612901&ids=133,102,113,103,126,115,128,108,109,120&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989691 INFO (qtp1373384942-18962) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k&sort=n_tf1+asc&wt=javabin&version=2} hits=68 status=0 QTime=3
[junit4] 2> 989692 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_d1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989693 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_d1+desc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k|[ff01::114]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612906&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989694 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612906&ids=11,111,146,113,135,103,138,129,140,131&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k|[ff01::114]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989695 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k|[ff01::114]:33332/x_k&sort=n_d1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 989696 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_d1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989698 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_d1+asc&shard.url=[ff01::083]:33332/x_k|[ff01::114]:33332/x_k|[ff01::213]:33332/x_k|http://127.0.0.1:41727/x_k/collection1&rows=10&version=2&q=*:*&NOW=1522607612909&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989699 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612909&ids=133,1,136,114,127,1001,117,8,9,119&isShard=true&shard.url=[ff01::083]:33332/x_k|[ff01::114]:33332/x_k|[ff01::213]:33332/x_k|http://127.0.0.1:41727/x_k/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989700 INFO (qtp1373384942-18962) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=[ff01::083]:33332/x_k|[ff01::114]:33332/x_k|[ff01::213]:33332/x_k|http://127.0.0.1:41727/x_k/collection1&sort=n_d1+asc&wt=javabin&version=2} hits=68 status=0 QTime=3
[junit4] 2> 989700 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_td1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989701 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_td1+desc&shard.url=[ff01::083]:33332/x_k|http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612914&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989702 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612914&ids=110,133,123,125,16,1001,129,108,109,141&isShard=true&shard.url=[ff01::083]:33332/x_k|http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989703 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=[ff01::083]:33332/x_k|http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k&sort=n_td1+desc&wt=javabin&version=2} hits=68 status=0 QTime=1
[junit4] 2> 989703 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_td1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989705 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_td1+asc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612917&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989706 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612917&ids=144,135,14,3,116,128,107,119,142,10&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989706 INFO (qtp1373384942-18962) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::114]:33332/x_k&sort=n_td1+asc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 989707 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_l1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989709 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_l1+desc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k|[ff01::114]:33332/x_k|[ff01::083]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612921&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989709 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612921&ids=11,100,2,135,113,104,115,16,17,116&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k|[ff01::114]:33332/x_k|[ff01::083]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989710 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k|[ff01::114]:33332/x_k|[ff01::083]:33332/x_k&sort=n_l1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 989711 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_l1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989712 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_l1+asc&shard.url=[ff01::213]:33332/x_k|http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k|[ff01::114]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612925&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989713 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612925&ids=110,121,111,114,5,126,138,1001,9,142&isShard=true&shard.url=[ff01::213]:33332/x_k|http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k|[ff01::114]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989714 INFO (qtp1373384942-18962) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=[ff01::213]:33332/x_k|http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k|[ff01::114]:33332/x_k&sort=n_l1+asc&wt=javabin&version=2} hits=68 status=0 QTime=1
[junit4] 2> 989714 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_tl1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989716 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tl1+desc&shard.url=http://127.0.0.1:41727/x_k/collection1&rows=10&version=2&q=*:*&NOW=1522607612928&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989717 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612928&ids=111,12,100,2,101,124,103,126,137,7&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989717 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1&sort=n_tl1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 989718 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_tl1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989719 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tl1+asc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k|[ff01::083]:33332/x_k|[ff01::114]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612932&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989720 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612932&ids=144,1,3,146,125,105,1001,117,109,142&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k|[ff01::083]:33332/x_k|[ff01::114]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989720 INFO (qtp1373384942-18962) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::213]:33332/x_k|[ff01::083]:33332/x_k|[ff01::114]:33332/x_k&sort=n_tl1+asc&wt=javabin&version=2} hits=68 status=0 QTime=1
[junit4] 2> 989721 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_dt1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989723 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_dt1+desc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612935&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989723 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612935&ids=1,134,102,113,15,4,125,17,106,118&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989724 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k&sort=n_dt1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 989725 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_dt1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989726 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_dt1+asc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612939&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989727 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612939&ids=110,111,136,126,16,116,1001,139,108,140&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989727 INFO (qtp1373384942-18962) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k&sort=n_dt1+asc&wt=javabin&version=2} hits=68 status=0 QTime=1
[junit4] 2> 989728 INFO (qtp1421154257-18950) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_tdt1+desc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989730 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tdt1+desc&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k|[ff01::213]:33332/x_k|[ff01::114]:33332/x_k&rows=10&version=2&q=*:*&NOW=1522607612942&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989730 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&df=text&distrib=false&shards.purpose=64&NOW=1522607612942&ids=110,121,100,144,112,146,102,14,147,9&isShard=true&shard.url=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k|[ff01::213]:33332/x_k|[ff01::114]:33332/x_k&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 989731 INFO (qtp1373384942-18965) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&shards=http://127.0.0.1:41727/x_k/collection1|[ff01::083]:33332/x_k|[ff01::213]:33332/x_k|[ff01::114]:33332/x_k&sort=n_tdt1+desc&wt=javabin&version=2} hits=68 status=0 QTime=2
[junit4] 2> 989732 INFO (qtp1421154257-18948) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*:*&distrib=false&sort=n_tdt1+asc&wt=javabin&version=2} hits=68 status=0 QTime=0
[junit4] 2> 989734 INFO (qtp1373384942-18961) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={df=text&distrib=false&fl=id&shards.purpose=4&start=0&fsv=true&sort=n_tdt1+asc&shard.url=http://127.0.0.1:41727/x_k/collection1&rows=10&version=2&q=*:*&NOW=1522607612946&isShard=true&wt=javabin} hits=68 status=0 QTime=0
[junit4] 2> 989735 INFO (qtp1373384942-18966) [ x:collection1] o.a.s.c.S.Request [collection1] webapp=/x_k path=/select params={q=*
[...truncated too long message...]
porter@3d4756fe: rootName = null, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@1c8aa913
[junit4] 2> 1008357 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1008357 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@2923f184: rootName = null, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@8de931c
[junit4] 2> 1008357 INFO (coreCloseExecutor-4175-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@ac1489f
[junit4] 2> 1008358 INFO (coreCloseExecutor-4175-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=180439199
[junit4] 2> 1008358 INFO (coreCloseExecutor-4175-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@342a4fad: rootName = null, domain = solr.core.collection1, service url = null, agent id = null] for registry solr.core.collection1 / com.codahale.metrics.MetricRegistry@ac7e5a7
[junit4] 2> 1008366 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@504042e8{/x_k,null,UNAVAILABLE}
[junit4] 2> 1008366 INFO (TEST-TestDistributedSearch.test-seed#[B6D2ACC38739EB8B]) [ ] o.e.j.s.session Stopped scavenging
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestDistributedSearch -Dtests.method=test -Dtests.seed=B6D2ACC38739EB8B -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=tk-TM -Dtests.timezone=America/Indiana/Marengo -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] FAILURE 20.5s J0 | TestDistributedSearch.test <<<
[junit4] > Throwable #1: java.lang.AssertionError: Expected to find shardAddress in the up shard info: {error=org.apache.solr.client.solrj.SolrServerException: Time allowed to handle this request exceeded,trace=org.apache.solr.client.solrj.SolrServerException: Time allowed to handle this request exceeded
[junit4] > at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:460)
[junit4] > at org.apache.solr.handler.component.HttpShardHandlerFactory.makeLoadBalancedRequest(HttpShardHandlerFactory.java:273)
[junit4] > at org.apache.solr.handler.component.HttpShardHandler.lambda$submit$0(HttpShardHandler.java:175)
[junit4] > at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[junit4] > at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514)
[junit4] > at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
[junit4] > at com.codahale.metrics.InstrumentedExecutorService$InstrumentedRunnable.run(InstrumentedExecutorService.java:176)
[junit4] > at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:192)
[junit4] > at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1135)
[junit4] > at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[junit4] > at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] > ,time=1}
[junit4] > at __randomizedtesting.SeedInfo.seed([B6D2ACC38739EB8B:3E86931929C58673]:0)
[junit4] > at org.apache.solr.TestDistributedSearch.comparePartialResponses(TestDistributedSearch.java:1191)
[junit4] > at org.apache.solr.TestDistributedSearch.queryPartialResults(TestDistributedSearch.java:1132)
[junit4] > at org.apache.solr.TestDistributedSearch.test(TestDistributedSearch.java:992)
[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 org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsRepeatStatement.callStatement(BaseDistributedSearchTestCase.java:1019)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase$ShardsRepeatRule$ShardsStatement.evaluate(BaseDistributedSearchTestCase.java:968)
[junit4] > at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.TestDistributedSearch_B6D2ACC38739EB8B-001
[junit4] 2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarity(queryNorm=false): {}, locale=tk-TM, timezone=America/Indiana/Marengo
[junit4] 2> NOTE: Linux 4.13.0-37-generic amd64/Oracle Corporation 10 (64-bit)/cpus=8,threads=1,free=261712168,total=495452160
[junit4] 2> NOTE: All tests run in this JVM: [TestFieldCacheSortRandom, TestRemoteStreaming, DistributedFacetPivotWhiteBoxTest, TestMergePolicyConfig, ReplicaListTransformerTest, SecurityConfHandlerTest, WrapperMergePolicyFactoryTest, TestPHPSerializedResponseWriter, TestSolr4Spatial2, TestRuleBasedAuthorizationPlugin, TestSegmentSorting, TermVectorComponentDistributedTest, SuggestComponentContextFilterQueryTest, TestLMDirichletSimilarityFactory, TestConfigSetProperties, TestSerializedLuceneMatchVersion, TestDistribDocBasedVersion, HighlighterConfigTest, TestWriterPerf, TestSchemalessBufferedUpdates, NodeMarkersRegistrationTest, SynonymTokenizerTest, SimpleFacetsTest, TestDistribIDF, V2StandaloneTest, TestLuceneMatchVersion, TestRandomFaceting, RegexBytesRefFilterTest, SearchRateTriggerTest, TestTolerantUpdateProcessorRandomCloud, TestCustomStream, TestAuthenticationFramework, TestMaxTokenLenTokenizer, TestIndexingPerformance, BasicDistributedZkTest, TestFastOutputStream, TestHalfAndHalfDocValues, TestCloudInspectUtil, ImplicitSnitchTest, TestHdfsUpdateLog, RAMDirectoryFactoryTest, TestRebalanceLeaders, TriLevelCompositeIdRoutingTest, InfoHandlerTest, CdcrReplicationHandlerTest, CursorPagingTest, OutputWriterTest, TestJsonFacetRefinement, ZkSolrClientTest, ExternalFileFieldSortTest, TestNestedDocsSort, TestClusterStateProvider, ConcurrentDeleteAndCreateCollectionTest, SolrPluginUtilsTest, BinaryUpdateRequestHandlerTest, SolrIndexSplitterTest, ExecutePlanActionTest, TestRetrieveFieldsOptimizer, TestMacros, TestSimDistributedQueue, DebugComponentTest, SpellingQueryConverterTest, TestGeoJSONResponseWriter, TestExclusionRuleCollectionAccess, TestUseDocValuesAsStored2, DistribJoinFromCollectionTest, BlobRepositoryCloudTest, TestFieldCache, TestNRTOpen, MetricsConfigTest, CollectionTooManyReplicasTest, DefaultValueUpdateProcessorTest, TestImpersonationWithHadoopAuth, TestNamedUpdateProcessors, TestStandardQParsers, TestCrossCoreJoin, DistributedExpandComponentTest, TestIndexSearcher, TestSkipOverseerOperations, TestMinMaxOnMultiValuedField, TestSolrCloudSnapshots, TestBinaryField, ZkCLITest, CoreAdminOperationTest, HttpSolrCallGetCoreTest, OutOfBoxZkACLAndCredentialsProvidersTest, HdfsChaosMonkeyNothingIsSafeTest, TestUnifiedSolrHighlighter, TestManagedResource, TestDynamicFieldResource, TestFieldTypeCollectionResource, ZkNodePropsTest, TestHashPartitioner, AtomicUpdateProcessorFactoryTest, DateRangeFieldTest, UUIDUpdateProcessorFallbackTest, HLLSerializationTest, CdcrBidirectionalTest, TestGroupingSearch, TestOmitPositions, TestConfigSetsAPIZkFailure, ChaosMonkeyNothingIsSafeWithPullReplicasTest, TestBinaryResponseWriter, SolrSlf4jReporterTest, SolrRequestParserTest, MBeansHandlerTest, TestLeaderInitiatedRecoveryThread, AliasIntegrationTest, TestManagedSynonymFilterFactory, HdfsRecoverLeaseTest, ConnectionReuseTest, DeleteNodeTest, PreAnalyzedUpdateProcessorTest, DistributedSuggestComponentTest, TestSchemaResource, ChaosMonkeyNothingIsSafeTest, TokenizerChainTest, TestIBSimilarityFactory, DocExpirationUpdateProcessorFactoryTest, OpenExchangeRatesOrgProviderTest, TestStressLiveNodes, ResponseBuilderTest, SolrIndexConfigTest, HttpPartitionTest, SolrGraphiteReporterTest, BadIndexSchemaTest, TestReRankQParserPlugin, TestSort, TestNodeAddedTrigger, OpenCloseCoreStressTest, ShardRoutingTest, ShardRoutingCustomTest, TestDistributedSearch]
[junit4] Completed [404/794 (1!)] on J0 in 20.51s, 1 test, 1 failure <<< FAILURES!
[...truncated 44192 lines...]
[repro] Jenkins log URL: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Linux/1630/consoleText
[repro] Revision: a2fcb8c9ed4a8e7fd0c23829c089573558a987f0
[repro] Ant options: "-Dargs=-XX:+UseCompressedOops -XX:+UseParallelGC"
[repro] Repro line: ant test -Dtestcase=TestDistributedSearch -Dtests.method=test -Dtests.seed=B6D2ACC38739EB8B -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=tk-TM -Dtests.timezone=America/Indiana/Marengo -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[repro] ant clean
[...truncated 6 lines...]
[repro] Test suites by module:
[repro] solr/core
[repro] TestDistributedSearch
[repro] ant compile-test
[...truncated 3319 lines...]
[repro] ant test-nocompile -Dtests.dups=5 -Dtests.maxfailures=5 -Dtests.class="*.TestDistributedSearch" -Dtests.showOutput=onerror "-Dargs=-XX:+UseCompressedOops -XX:+UseParallelGC" -Dtests.seed=B6D2ACC38739EB8B -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=tk-TM -Dtests.timezone=America/Indiana/Marengo -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[...truncated 76 lines...]
[repro] Failures:
[repro] 0/5 failed: org.apache.solr.TestDistributedSearch
[repro] Exiting with code 0
[...truncated 40 lines...]
[JENKINS] Lucene-Solr-7.x-Linux (64bit/jdk-9.0.4) - Build # 1631 -
Still Unstable!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Linux/1631/
Java: 64bit/jdk-9.0.4 -XX:+UseCompressedOops -XX:+UseParallelGC
1 tests failed.
FAILED: org.apache.solr.cloud.hdfs.HDFSCollectionsAPITest.testDataDirIsNotReused
Error Message:
null Live Nodes: [127.0.0.1:34345_solr, 127.0.0.1:35105_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:38129/data/test/core_node2/data/", "base_url":"https://127.0.0.1:34345/solr", "node_name":"127.0.0.1:34345_solr", "type":"NRT", "ulogDir":"hdfs://localhost.localdomain:38129/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:34345_solr, 127.0.0.1:35105_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:38129/data/test/core_node2/data/",
"base_url":"https://127.0.0.1:34345/solr",
"node_name":"127.0.0.1:34345_solr",
"type":"NRT",
"ulogDir":"hdfs://localhost.localdomain:38129/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([C2DFCCA168D328D7:DAC08ED57B8A8A70]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.SolrCloudTestCase.waitForState(SolrCloudTestCase.java:269)
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 1796 lines...]
[junit4] JVM J0: stdout was not empty, see: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/lucene/build/core/test/temp/junit4-J0-20180401_221410_37414108589221762589529.sysout
[junit4] >>> JVM J0 emitted unexpected output (verbatim) ----
[junit4] codec: HighCompressionCompressingStoredFields, pf: Asserting, dvf: Direct
[junit4] <<< JVM J0: EOF ----
[...truncated 12702 lines...]
[junit4] Suite: org.apache.solr.cloud.hdfs.HDFSCollectionsAPITest
[junit4] 2> 1736056 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/init-core-data-001
[junit4] 2> 1736056 WARN (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=26 numCloses=26
[junit4] 2> 1736056 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 1736057 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason="", value=0.0/0.0, ssl=0.0/0.0, clientAuth=0.0/0.0)
[junit4] 2> 1736057 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-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/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-001
[junit4] 2> 1736057 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1736058 INFO (Thread-5379) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1736058 INFO (Thread-5379) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1736059 ERROR (Thread-5379) [ ] 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> 1736158 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:34001
[junit4] 2> 1736159 INFO (zkConnectionManagerCallback-11330-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1736161 INFO (jetty-launcher-11327-thread-1) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-22T08:27:37+11:00, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 1736161 INFO (jetty-launcher-11327-thread-2) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-22T08:27:37+11:00, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 1736162 INFO (jetty-launcher-11327-thread-1) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1736162 INFO (jetty-launcher-11327-thread-1) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1736162 INFO (jetty-launcher-11327-thread-1) [ ] o.e.j.s.session Scavenging every 600000ms
[junit4] 2> 1736162 INFO (jetty-launcher-11327-thread-2) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1736162 INFO (jetty-launcher-11327-thread-2) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1736162 INFO (jetty-launcher-11327-thread-2) [ ] o.e.j.s.session Scavenging every 600000ms
[junit4] 2> 1736162 INFO (jetty-launcher-11327-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@46bceb42{/solr,null,AVAILABLE}
[junit4] 2> 1736162 INFO (jetty-launcher-11327-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@5d24d7d8{/solr,null,AVAILABLE}
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1abbecd3{SSL,[ssl, http/1.1]}{127.0.0.1:34345}
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@284ec831{SSL,[ssl, http/1.1]}{127.0.0.1:35105}
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-2) [ ] o.e.j.s.Server Started @1736204ms
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-1) [ ] o.e.j.s.Server Started @1736204ms
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=35105}
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34345}
[junit4] 2> 1736164 ERROR (jetty-launcher-11327-thread-1) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1736164 ERROR (jetty-launcher-11327-thread-2) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-1) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-2) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.4.0
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.4.0
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-04-01T23:05:50.937675Z
[junit4] 2> 1736164 INFO (jetty-launcher-11327-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-04-01T23:05:50.937682Z
[junit4] 2> 1736165 INFO (zkConnectionManagerCallback-11334-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1736165 INFO (zkConnectionManagerCallback-11333-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1736165 INFO (jetty-launcher-11327-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1736165 INFO (jetty-launcher-11327-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1736176 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn Unable to read additional data from client sessionid 0x1000870486e0002, likely client has closed socket
[junit4] 2> 1736178 INFO (jetty-launcher-11327-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34001/solr
[junit4] 2> 1736178 INFO (jetty-launcher-11327-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34001/solr
[junit4] 2> 1736179 INFO (zkConnectionManagerCallback-11341-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1736179 INFO (zkConnectionManagerCallback-11342-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1736180 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn Unable to read additional data from client sessionid 0x1000870486e0004, likely client has closed socket
[junit4] 2> 1736180 INFO (zkConnectionManagerCallback-11344-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1736180 INFO (zkConnectionManagerCallback-11346-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1736213 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 1736213 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:35105_solr
[junit4] 2> 1736213 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.c.Overseer Overseer (id=72066872382455813-127.0.0.1:35105_solr-n_0000000000) starting
[junit4] 2> 1736213 INFO (jetty-launcher-11327-thread-2) [n:127.0.0.1:34345_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 1736214 INFO (jetty-launcher-11327-thread-2) [n:127.0.0.1:34345_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34345_solr
[junit4] 2> 1736214 INFO (zkCallback-11343-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1736217 INFO (zkCallback-11345-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1736217 INFO (zkConnectionManagerCallback-11352-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1736217 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1736218 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:34001/solr ready
[junit4] 2> 1736219 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 1736219 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35105_solr
[junit4] 2> 1736220 INFO (zkCallback-11343-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1736220 INFO (zkCallback-11351-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1736220 INFO (zkCallback-11345-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1736317 INFO (jetty-launcher-11327-thread-2) [n:127.0.0.1:34345_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34345.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1736322 INFO (jetty-launcher-11327-thread-2) [n:127.0.0.1:34345_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34345.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1736322 INFO (jetty-launcher-11327-thread-2) [n:127.0.0.1:34345_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34345.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1736323 INFO (jetty-launcher-11327-thread-2) [n:127.0.0.1:34345_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-001/node2/.
[junit4] 2> 1736325 INFO (zkConnectionManagerCallback-11356-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1736326 INFO (jetty-launcher-11327-thread-2) [n:127.0.0.1:34345_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1736326 INFO (jetty-launcher-11327-thread-2) [n:127.0.0.1:34345_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:34001/solr ready
[junit4] 2> 1736405 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_35105.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1736410 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_35105.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1736410 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_35105.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1736410 INFO (jetty-launcher-11327-thread-1) [n:127.0.0.1:35105_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-001/node1/.
[junit4] 2> 1736423 INFO (zkConnectionManagerCallback-11358-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 1> Formatting using clusterid: testClusterID
[junit4] 2> 1736520 WARN (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.h.m.i.MetricsConfig Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
[junit4] 2> 1736524 WARN (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 1736525 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.m.log jetty-6.1.x
[junit4] 2> 1736530 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-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_33197_hdfs____2akfpl/webapp
[junit4] 2> 1736592 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost.localdomain:33197
[junit4] 2> 1736652 WARN (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 1736653 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.m.log jetty-6.1.x
[junit4] 2> 1736656 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-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_39975_datanode____.entn8o/webapp
[junit4] 2> 1736722 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:39975
[junit4] 2> 1736760 WARN (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 1736761 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.m.log jetty-6.1.x
[junit4] 2> 1736775 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-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_37393_datanode____.cbnd2o/webapp
[junit4] 2> 1736835 ERROR (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-002/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-002/hdfsBaseDir/data/data2/]] heartbeating to localhost.localdomain/127.0.0.1:38129) [ ] 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> 1736839 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x80c37bb5608d: from storage DS-1c89fde8-0808-47f4-a472-b8bac6df1b32 node DatanodeRegistration(127.0.0.1:36185, datanodeUuid=4a52578d-1e18-4c8f-bb8b-3b732b5a282d, infoPort=43305, infoSecurePort=0, ipcPort=36229, storageInfo=lv=-56;cid=testClusterID;nsid=2011659549;c=0), blocks: 0, hasStaleStorage: true, processing time: 0 msecs
[junit4] 2> 1736839 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x80c37bb5608d: from storage DS-1376ce70-4b00-42c7-92ca-9e1ee7e0439d node DatanodeRegistration(127.0.0.1:36185, datanodeUuid=4a52578d-1e18-4c8f-bb8b-3b732b5a282d, infoPort=43305, infoSecurePort=0, ipcPort=36229, storageInfo=lv=-56;cid=testClusterID;nsid=2011659549;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
[junit4] 2> 1736852 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:37393
[junit4] 2> 1736947 ERROR (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-002/hdfsBaseDir/data/data3/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-002/hdfsBaseDir/data/data4/]] heartbeating to localhost.localdomain/127.0.0.1:38129) [ ] 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> 1736952 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x80c3826d0a09: from storage DS-f3acaa70-6655-418d-878a-e17aef9f84ad node DatanodeRegistration(127.0.0.1:42385, datanodeUuid=c2fdaa7d-60a6-4dc6-99e2-be4da8239958, infoPort=40545, infoSecurePort=0, ipcPort=34463, storageInfo=lv=-56;cid=testClusterID;nsid=2011659549;c=0), blocks: 0, hasStaleStorage: true, processing time: 0 msecs
[junit4] 2> 1736952 INFO (Block report processor) [ ] BlockStateChange BLOCK* processReport 0x80c3826d0a09: from storage DS-725e97ad-e26c-487d-9f86-dc5c8cbf685c node DatanodeRegistration(127.0.0.1:42385, datanodeUuid=c2fdaa7d-60a6-4dc6-99e2-be4da8239958, infoPort=40545, infoSecurePort=0, ipcPort=34463, storageInfo=lv=-56;cid=testClusterID;nsid=2011659549;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
[junit4] 2> 1736974 INFO (zkConnectionManagerCallback-11362-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1736974 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1736975 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:34001/solr ready
[junit4] 2> 1737007 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testDataDirIsNotReused
[junit4] 2> 1737017 INFO (qtp1522650580-31683) [n:127.0.0.1:35105_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf1&name=test&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=127.0.0.1:34345_solr&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 1737018 INFO (OverseerThreadFactory-8937-thread-1) [ ] o.a.s.c.a.c.CreateCollectionCmd Create collection test
[junit4] 2> 1737122 INFO (OverseerStateUpdate-72066872382455813-127.0.0.1:35105_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:34345/solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "waitForFinalState":"false"}
[junit4] 2> 1737334 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr ] 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> 1737334 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 1737437 INFO (zkCallback-11345-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> 1737437 INFO (zkCallback-11345-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: [2])
[junit4] 2> 1738341 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.4.0
[junit4] 2> 1738344 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1738345 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1738345 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1738346 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34345.solr.core.test.shard1.replica_n1' (registry 'solr.core.test.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1738346 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://localhost.localdomain:38129/data
[junit4] 2> 1738346 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 1738346 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 1738346 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-001/node2/test_shard1_replica_n1], dataDir=[hdfs://localhost.localdomain:38129/data/test/core_node2/data/]
[junit4] 2> 1738347 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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:38129/data/test/core_node2/data/snapshot_metadata
[junit4] 2> 1738354 WARN (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.h.HdfsDirectory The NameNode is in SafeMode - Solr will wait 5 seconds and try again.
[junit4] 2> 1743364 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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:38129/data/test/core_node2/data
[junit4] 2> 1743376 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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:38129/data/test/core_node2/data/index
[junit4] 2> 1743397 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741825_1001{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1376ce70-4b00-42c7-92ca-9e1ee7e0439d:NORMAL:127.0.0.1:36185|RBW], ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|RBW]]} size 0
[junit4] 2> 1743398 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741825_1001 size 69
[junit4] 2> 1743898 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1743898 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1743898 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=3
[junit4] 2> 1743907 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1743907 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1743918 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5f1491f[test_shard1_replica_n1] main]
[junit4] 2> 1743918 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1743919 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1743919 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1743920 INFO (searcherExecutor-8942-thread-1-processing-n:127.0.0.1:34345_solr x:test_shard1_replica_n1 c:test s:shard1 r:core_node2) [n:127.0.0.1:34345_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@5f1491f[test_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1743920 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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 1596586940110471168
[junit4] 2> 1743923 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1743924 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1743924 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1743924 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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:34345/solr/test_shard1_replica_n1/
[junit4] 2> 1743924 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1743924 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.c.SyncStrategy https://127.0.0.1:34345/solr/test_shard1_replica_n1/ has no replicas
[junit4] 2> 1743924 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1743925 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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:34345/solr/test_shard1_replica_n1/ shard1
[junit4] 2> 1743926 INFO (zkCallback-11345-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: [2])
[junit4] 2> 1743926 INFO (zkCallback-11345-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> 1743975 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1744011 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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=6677
[junit4] 2> 1744013 INFO (qtp1522650580-31683) [n:127.0.0.1:35105_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> 1744078 INFO (zkCallback-11345-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> 1744078 INFO (zkCallback-11345-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: [2])
[junit4] 2> 1745015 INFO (qtp1522650580-31683) [n:127.0.0.1:35105_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf1&name=test&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=127.0.0.1:34345_solr&wt=javabin&version=2} status=0 QTime=7997
[junit4] 2> 1745020 INFO (OverseerCollectionConfigSetProcessor-72066872382455813-127.0.0.1:35105_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> 1745021 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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> 1745030 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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 (1596586941261807616)]} 0 12
[junit4] 2> 1745033 INFO (qtp1947424336-31684) [n:127.0.0.1:34345_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 (1596586941275439104)]} 0 1
[junit4] 2> 1745033 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.DirectUpdateHandler2 start commit{_version_=1596586941277536256,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 1745033 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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@4fd2ec05 commitCommandVersion:1596586941277536256
[junit4] 2> 1745042 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741827_1003{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|RBW], ReplicaUC[[DISK]DS-1c89fde8-0808-47f4-a472-b8bac6df1b32:NORMAL:127.0.0.1:36185|FINALIZED]]} size 0
[junit4] 2> 1745042 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741827_1003 size 200
[junit4] 2> 1745049 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741828_1004{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-725e97ad-e26c-487d-9f86-dc5c8cbf685c:NORMAL:127.0.0.1:42385|RBW], ReplicaUC[[DISK]DS-1376ce70-4b00-42c7-92ca-9e1ee7e0439d:NORMAL:127.0.0.1:36185|FINALIZED]]} size 0
[junit4] 2> 1745049 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741828_1004 size 69
[junit4] 2> 1745059 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741829_1005{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1c89fde8-0808-47f4-a472-b8bac6df1b32:NORMAL:127.0.0.1:36185|RBW], ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|RBW]]} size 0
[junit4] 2> 1745059 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741829_1005 size 424
[junit4] 2> 1745069 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741830_1006{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1c89fde8-0808-47f4-a472-b8bac6df1b32:NORMAL:127.0.0.1:36185|RBW], ReplicaUC[[DISK]DS-725e97ad-e26c-487d-9f86-dc5c8cbf685c:NORMAL:127.0.0.1:42385|FINALIZED]]} size 0
[junit4] 2> 1745069 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741830_1006 size 59
[junit4] 2> 1745075 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741831_1007{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1c89fde8-0808-47f4-a472-b8bac6df1b32:NORMAL:127.0.0.1:36185|RBW], ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|FINALIZED]]} size 0
[junit4] 2> 1745075 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741831_1007 size 83
[junit4] 2> 1745082 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741832_1008{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-725e97ad-e26c-487d-9f86-dc5c8cbf685c:NORMAL:127.0.0.1:42385|RBW], ReplicaUC[[DISK]DS-1376ce70-4b00-42c7-92ca-9e1ee7e0439d:NORMAL:127.0.0.1:36185|FINALIZED]]} size 0
[junit4] 2> 1745082 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741832_1008 size 101
[junit4] 2> 1745088 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741833_1009{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1c89fde8-0808-47f4-a472-b8bac6df1b32:NORMAL:127.0.0.1:36185|RBW], ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|FINALIZED]]} size 0
[junit4] 2> 1745088 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741833_1009{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1c89fde8-0808-47f4-a472-b8bac6df1b32:NORMAL:127.0.0.1:36185|RBW], ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|FINALIZED]]} size 0
[junit4] 2> 1745096 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741834_1010{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1376ce70-4b00-42c7-92ca-9e1ee7e0439d:NORMAL:127.0.0.1:36185|RBW], ReplicaUC[[DISK]DS-725e97ad-e26c-487d-9f86-dc5c8cbf685c:NORMAL:127.0.0.1:42385|FINALIZED]]} size 0
[junit4] 2> 1745097 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741834_1010 size 111
[junit4] 2> 1745097 WARN (DataStreamer for file /data/test/core_node2/data/index/_0.fdt block BP-1541870851-88.99.242.108-1522623951219:blk_1073741834_1010) [ ] o.a.h.h.DFSClient Caught exception
[junit4] 2> java.lang.InterruptedException: null
[junit4] 2> at java.lang.Object.wait(Native Method) ~[?:?]
[junit4] 2> at java.lang.Thread.join(Thread.java:1353) ~[?:?]
[junit4] 2> at java.lang.Thread.join(Thread.java:1427) ~[?:?]
[junit4] 2> at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.closeResponder(DFSOutputStream.java:716) [hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.closeInternal(DFSOutputStream.java:684) [hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> at org.apache.hadoop.hdfs.DFSOutputStream$DataStreamer.run(DFSOutputStream.java:680) [hadoop-hdfs-2.7.4.jar:?]
[junit4] 2> 1745107 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741835_1011{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1376ce70-4b00-42c7-92ca-9e1ee7e0439d:NORMAL:127.0.0.1:36185|RBW], ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|FINALIZED]]} size 0
[junit4] 2> 1745109 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741835_1011{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|FINALIZED], ReplicaUC[[DISK]DS-1c89fde8-0808-47f4-a472-b8bac6df1b32:NORMAL:127.0.0.1:36185|FINALIZED]]} size 0
[junit4] 2> 1745119 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741836_1012{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|RBW], ReplicaUC[[DISK]DS-1376ce70-4b00-42c7-92ca-9e1ee7e0439d:NORMAL:127.0.0.1:36185|FINALIZED]]} size 0
[junit4] 2> 1745119 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741836_1012 size 172
[junit4] 2> 1745139 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@60b4f29d[test_shard1_replica_n1] main]
[junit4] 2> 1745140 INFO (searcherExecutor-8942-thread-1-processing-n:127.0.0.1:34345_solr x:test_shard1_replica_n1 c:test s:shard1 r:core_node2) [n:127.0.0.1:34345_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@60b4f29d[test_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.4.0):C2)))}
[junit4] 2> 1745142 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741826_1002{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-725e97ad-e26c-487d-9f86-dc5c8cbf685c:NORMAL:127.0.0.1:42385|RBW], ReplicaUC[[DISK]DS-1376ce70-4b00-42c7-92ca-9e1ee7e0439d:NORMAL:127.0.0.1:36185|RBW]]} size 75
[junit4] 2> 1745142 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741826_1002 size 139
[junit4] 2> 1745142 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_solr c:test s:shard1 r:core_node2 x:test_shard1_replica_n1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 1745142 INFO (qtp1947424336-31681) [n:127.0.0.1:34345_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 109
[junit4] 2> 1745154 INFO (qtp1947424336-31684) [n:127.0.0.1:34345_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 (1596586941392879616)]} 0 10
[junit4] 2> 1745155 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@1abbecd3{SSL,[ssl, http/1.1]}{127.0.0.1:0}
[junit4] 2> 1745155 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=164539855
[junit4] 2> 1745155 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1745155 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@3bc6b011: rootName = solr_34345, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@1f7dcc23
[junit4] 2> 1745160 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 1745160 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@73cba932: rootName = solr_34345, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@34e60a53
[junit4] 2> 1745163 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1745163 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@2d5c44f3: rootName = solr_34345, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@2cc19187
[junit4] 2> 1745164 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:34345_solr
[junit4] 2> 1745164 INFO (zkCallback-11355-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1745164 INFO (zkCallback-11351-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1745164 INFO (zkCallback-11345-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1745164 INFO (zkCallback-11343-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1745164 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 1745164 INFO (zkCallback-11361-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 1745165 INFO (coreCloseExecutor-8947-thread-1) [n:127.0.0.1:34345_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@3eb44963
[junit4] 2> 1745165 INFO (coreCloseExecutor-8947-thread-1) [n:127.0.0.1:34345_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=1052002659
[junit4] 2> 1745165 INFO (coreCloseExecutor-8947-thread-1) [n:127.0.0.1:34345_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@6e2815da: rootName = solr_34345, 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@3be5678
[junit4] 2> 1745170 INFO (coreCloseExecutor-8947-thread-1) [n:127.0.0.1:34345_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=1052002659
[junit4] 2> 1745175 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741837_1013{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|RBW], ReplicaUC[[DISK]DS-1c89fde8-0808-47f4-a472-b8bac6df1b32:NORMAL:127.0.0.1:36185|RBW]]} size 75
[junit4] 2> 1745175 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741837_1013{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-f3acaa70-6655-418d-878a-e17aef9f84ad:NORMAL:127.0.0.1:42385|RBW], ReplicaUC[[DISK]DS-1c89fde8-0808-47f4-a472-b8bac6df1b32:NORMAL:127.0.0.1:36185|RBW]]} size 75
[junit4] 2> 1745176 INFO (coreCloseExecutor-8947-thread-1) [n:127.0.0.1:34345_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:38129/data/test/core_node2/data/snapshot_metadata
[junit4] 2> 1745176 INFO (coreCloseExecutor-8947-thread-1) [n:127.0.0.1:34345_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:38129/data/test/core_node2/data
[junit4] 2> 1745176 INFO (coreCloseExecutor-8947-thread-1) [n:127.0.0.1:34345_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:38129/data/test/core_node2/data/index
[junit4] 2> 1745177 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:529) [java/:?]
[junit4] 2> at org.apache.solr.core.SolrCore.lambda$cleanupOldIndexDirectories$21(SolrCore.java:3037) [java/:?]
[junit4] 2> at java.lang.Thread.run(Thread.java:844) [?:?]
[junit4] 2> 1745178 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@5d24d7d8{/solr,null,UNAVAILABLE}
[junit4] 2> 1745178 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.e.j.s.session Stopped scavenging
[junit4] 2> 1745265 INFO (zkCallback-11361-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> 1745265 INFO (zkCallback-11361-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> 1745265 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1745266 INFO (OverseerThreadFactory-8937-thread-2) [ ] o.a.s.c.a.c.OverseerCollectionMessageHandler Executing Collection Cmd=action=UNLOAD&deleteInstanceDir=true&deleteDataDir=true, asyncId=null
[junit4] 2> 1745972 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={name=test&action=DELETE&wt=javabin&version=2} status=0 QTime=706
[junit4] 2> 1745973 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.e.j.s.Server jetty-9.4.8.v20171121, build timestamp: 2017-11-22T08:27:37+11:00, git hash: 82b8fb23f757335bb3329d540ce37a2a2615f0a8
[junit4] 2> 1745973 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.e.j.s.session DefaultSessionIdManager workerName=node0
[junit4] 2> 1745973 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.e.j.s.session No SessionScavenger set, using defaults
[junit4] 2> 1745973 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.e.j.s.session Scavenging every 660000ms
[junit4] 2> 1745974 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@2b21ac18{/solr,null,AVAILABLE}
[junit4] 2> 1745974 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.e.j.s.AbstractConnector Started ServerConnector@645c1423{SSL,[ssl, http/1.1]}{127.0.0.1:34345}
[junit4] 2> 1745974 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.e.j.s.Server Started @1746014ms
[junit4] 2> 1745974 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34345}
[junit4] 2> 1745974 ERROR (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1745974 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.s.SolrDispatchFilter Using logger factory org.apache.logging.slf4j.Log4jLoggerFactory
[junit4] 2> 1745974 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 7.4.0
[junit4] 2> 1745974 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1745974 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1745974 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-04-01T23:06:00.747821Z
[junit4] 2> 1745975 INFO (zkConnectionManagerCallback-11364-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1745975 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1745980 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:34001/solr
[junit4] 2> 1745980 INFO (zkConnectionManagerCallback-11368-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1745982 INFO (zkConnectionManagerCallback-11370-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1745985 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1745985 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 1745987 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 1745987 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34345_solr
[junit4] 2> 1745988 INFO (zkCallback-11343-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1745988 INFO (zkCallback-11361-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1745988 INFO (zkCallback-11351-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1745992 INFO (zkCallback-11369-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1746082 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34345.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1746089 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34345.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1746089 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_34345.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1746090 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.c.CorePropertiesLocator Found 1 core definitions underneath /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-001/node2/.
[junit4] 2> 1746090 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.c.CorePropertiesLocator Cores are: [test_shard1_replica_n1]
[junit4] 2> 1746092 INFO (zkConnectionManagerCallback-11375-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 1746092 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1746092 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [n:127.0.0.1:34345_solr ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:34001/solr ready
[junit4] 2> 1747267 INFO (OverseerCollectionConfigSetProcessor-72066872382455813-127.0.0.1:35105_solr-n_0000000000) [ ] 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> 1756092 ERROR (coreContainerWorkExecutor-8950-thread-1-processing-n:127.0.0.1:34345_solr) [n:127.0.0.1:34345_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:1739) ~[java/:?]
[junit4] 2> at org.apache.solr.cloud.ZkController.preRegister(ZkController.java:1637) ~[java/:?]
[junit4] 2> at org.apache.solr.core.CoreContainer.createFromDescriptor(CoreContainer.java:1033) ~[java/:?]
[junit4] 2> at org.apache.solr.core.CoreContainer.lambda$load$13(CoreContainer.java:640) ~[java/:?]
[junit4] 2> at com.codahale.metrics.InstrumentedExecutorService$InstrumentedCallable.call(InstrumentedExecutorService.java:197) ~[metrics-core-3.2.2.jar:3.2.2]
[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:192) [java/:?]
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) [?:?]
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) [?:?]
[junit4] 2> at java.lang.Thread.run(Thread.java:844) [?:?]
[junit4] 2> 1756100 INFO (qtp1660765665-32038) [n:127.0.0.1:34345_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=1&collection.configName=conf1&name=test&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=127.0.0.1:35105_solr&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 1756102 INFO (OverseerThreadFactory-8937-thread-3) [ ] o.a.s.c.a.c.CreateCollectionCmd Create collection test
[junit4] 2> 1756206 INFO (OverseerStateUpdate-72066872382455813-127.0.0.1:35105_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_n3",
[junit4] 2> "state":"down",
[junit4] 2> "base_url":"https://127.0.0.1:35105/solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "waitForFinalState":"false"}
[junit4] 2> 1756409 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr ] 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> 1756511 INFO (zkCallback-11343-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> 1756511 INFO (zkCallback-11343-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: [2])
[junit4] 2> 1757423 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SolrConfig Using Lucene MatchVersion: 7.4.0
[junit4] 2> 1757428 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757429 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757429 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757429 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_35105.solr.core.test.shard1.replica_n3' (registry 'solr.core.test.shard1.replica_n3') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@5436eb9f
[junit4] 2> 1757430 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://localhost.localdomain:38129/data
[junit4] 2> 1757430 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 1757430 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 1757430 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-001/node1/test_shard1_replica_n3], dataDir=[hdfs://localhost.localdomain:38129/data/test/core_node4/data/]
[junit4] 2> 1757431 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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:38129/data/test/core_node4/data/snapshot_metadata
[junit4] 2> 1757443 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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:38129/data/test/core_node4/data
[junit4] 2> 1757458 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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:38129/data/test/core_node4/data/index
[junit4] 2> 1757479 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:42385 is added to blk_1073741838_1014{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1376ce70-4b00-42c7-92ca-9e1ee7e0439d:NORMAL:127.0.0.1:36185|RBW], ReplicaUC[[DISK]DS-725e97ad-e26c-487d-9f86-dc5c8cbf685c:NORMAL:127.0.0.1:42385|RBW]]} size 0
[junit4] 2> 1757479 INFO (Block report processor) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:36185 is added to blk_1073741838_1014{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-1376ce70-4b00-42c7-92ca-9e1ee7e0439d:NORMAL:127.0.0.1:36185|RBW], ReplicaUC[[DISK]DS-725e97ad-e26c-487d-9f86-dc5c8cbf685c:NORMAL:127.0.0.1:42385|RBW]]} size 0
[junit4] 2> 1757512 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757512 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757512 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=3
[junit4] 2> 1757519 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1757519 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1757528 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.s.SolrIndexSearcher Opening [Searcher@678a5f52[test_shard1_replica_n3] main]
[junit4] 2> 1757529 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757529 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757530 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757531 INFO (searcherExecutor-8955-thread-1-processing-n:127.0.0.1:35105_solr x:test_shard1_replica_n3 c:test s:shard1 r:core_node4) [n:127.0.0.1:35105_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@678a5f52[test_shard1_replica_n3] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1757531 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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 1596586954382639104
[junit4] 2> 1757534 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757535 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757535 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757535 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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:35105/solr/test_shard1_replica_n3/
[junit4] 2> 1757535 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757535 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SyncStrategy https://127.0.0.1:35105/solr/test_shard1_replica_n3/ has no replicas
[junit4] 2> 1757535 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757536 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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:35105/solr/test_shard1_replica_n3/ shard1
[junit4] 2> 1757637 INFO (zkCallback-11343-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: [2])
[junit4] 2> 1757637 INFO (zkCallback-11343-thread-3) [ ] 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> 1757686 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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> 1757692 INFO (qtp1522650580-31680) [n:127.0.0.1:35105_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=1283
[junit4] 2> 1757693 INFO (qtp1660765665-32038) [n:127.0.0.1:34345_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> 1757788 INFO (zkCallback-11343-thread-3) [ ] 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> 1757788 INFO (zkCallback-11343-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: [2])
[junit4] 2> 1758103 INFO (OverseerCollectionConfigSetProcessor-72066872382455813-127.0.0.1:35105_solr-n_0000000000) [ ] 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> 1758695 INFO (qtp1660765665-32038) [n:127.0.0.1:34345_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={replicationFactor=1&collection.configName=conf1&name=test&nrtReplicas=1&action=CREATE&numShards=1&createNodeSet=127.0.0.1:35105_solr&wt=javabin&version=2} status=0 QTime=2594
[junit4] 2> 1848696 INFO (TEST-HDFSCollectionsAPITest.testDataDirIsNotReused-seed#[C2DFCCA168D328D7]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testDataDirIsNotReused
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=HDFSCollectionsAPITest -Dtests.method=testDataDirIsNotReused -Dtests.seed=C2DFCCA168D328D7 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=mn-MN -Dtests.timezone=Asia/Yangon -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] FAILURE 112s J0 | HDFSCollectionsAPITest.testDataDirIsNotReused <<<
[junit4] > Throwable #1: java.lang.AssertionError:
[junit4] > null
[junit4] > Live Nodes: [127.0.0.1:34345_solr, 127.0.0.1:35105_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:38129/data/test/core_node2/data/",
[junit4] > "base_url":"https://127.0.0.1:34345/solr",
[junit4] > "node_name":"127.0.0.1:34345_solr",
[junit4] > "type":"NRT",
[junit4] > "ulogDir":"hdfs://localhost.localdomain:38129/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([C2DFCCA168D328D7:DAC08ED57B8A8A70]:0)
[junit4] > at org.apache.solr.cloud.SolrCloudTestCase.waitForState(SolrCloudTestCase.java:269)
[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> 1848717 INFO (jetty-closer-11328-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@645c1423{SSL,[ssl, http/1.1]}{127.0.0.1:34345}
[junit4] 2> 1848733 INFO (jetty-closer-11328-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=209651689
[junit4] 2> 1848733 INFO (jetty-closer-11328-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1848733 INFO (jetty-closer-11328-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@67848890: rootName = solr_34345, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@fe6d26a
[junit4] 2> 1848733 INFO (jetty-closer-11328-thread-2) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@284ec831{SSL,[ssl, http/1.1]}{127.0.0.1:0}
[junit4] 2> 1848734 INFO (jetty-closer-11328-thread-2) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1064615061
[junit4] 2> 1848734 INFO (jetty-closer-11328-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 1848734 INFO (jetty-closer-11328-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@5a60bd53: rootName = solr_35105, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@4c173e6f
[junit4] 2> 1848765 INFO (jetty-closer-11328-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 1848765 INFO (jetty-closer-11328-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@164b84f4: rootName = solr_35105, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@34e60a53
[junit4] 2> 1848775 INFO (jetty-closer-11328-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 1848775 INFO (jetty-closer-11328-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@2cc34186: rootName = solr_34345, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@34e60a53
[junit4] 2> 1848777 INFO (jetty-closer-11328-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1848777 INFO (jetty-closer-11328-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@6f1ffac0: rootName = solr_35105, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@2cc19187
[junit4] 2> 1848781 INFO (jetty-closer-11328-thread-2) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:35105_solr
[junit4] 2> 1848782 INFO (jetty-closer-11328-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 1848785 INFO (jetty-closer-11328-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 1848785 INFO (jetty-closer-11328-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@2171c67e: rootName = solr_34345, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@2cc19187
[junit4] 2> 1848785 INFO (zkCallback-11343-thread-4) [ ] 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> 1848786 INFO (zkCallback-11343-thread-6) [ ] 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> 1848786 INFO (jetty-closer-11328-thread-1) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:34345_solr
[junit4] 2> 1848786 INFO (jetty-closer-11328-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 1848793 INFO (zkCallback-11374-thread-1) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (0)
[junit4] 2> 1848800 INFO (zkCallback-11351-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (0)
[junit4] 2> 1848806 INFO (zkCallback-11369-thread-2) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (0)
[junit4] 2> 1848808 INFO (coreCloseExecutor-8960-thread-1) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.c.SolrCore [test_shard1_replica_n3] CLOSING SolrCore org.apache.solr.core.SolrCore@37c690bc
[junit4] 2> 1848808 INFO (coreCloseExecutor-8960-thread-1) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.test.shard1.replica_n3, tag=935760060
[junit4] 2> 1848808 INFO (coreCloseExecutor-8960-thread-1) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@33e09920: rootName = solr_35105, domain = solr.core.test.shard1.replica_n3, service url = null, agent id = null] for registry solr.core.test.shard1.replica_n3 / com.codahale.metrics.MetricRegistry@42516343
[junit4] 2> 1848816 INFO (coreCloseExecutor-8960-thread-1) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.test.shard1.leader, tag=935760060
[junit4] 2> 1848826 INFO (jetty-closer-11328-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@2b21ac18{/solr,null,UNAVAILABLE}
[junit4] 2> 1848827 INFO (jetty-closer-11328-thread-1) [ ] o.e.j.s.session Stopped scavenging
[junit4] 2> 1848828 INFO (zkCallback-11343-thread-7) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (0)
[junit4] 2> 1848879 INFO (coreCloseExecutor-8960-thread-1) [n:127.0.0.1:35105_solr c:test s:shard1 r:core_node4 x:test_shard1_replica_n3] o.a.s.s.h.HdfsDirectory Closing hdfs direct
[...truncated too long message...]
ionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.m.log Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:0
[junit4] 2> 1849890 WARN (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-002/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-002/hdfsBaseDir/data/data2/]] heartbeating to localhost.localdomain/127.0.0.1:38129) [ ] o.a.h.h.s.d.IncrementalBlockReportManager IncrementalBlockReportManager interrupted
[junit4] 2> 1849890 WARN (DataNode: [[[DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-002/hdfsBaseDir/data/data1/, [DISK]file:/home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001/tempDir-002/hdfsBaseDir/data/data2/]] heartbeating to localhost.localdomain/127.0.0.1:38129) [ ] o.a.h.h.s.d.DataNode Ending block pool service for: Block pool BP-1541870851-88.99.242.108-1522623951219 (Datanode Uuid 4a52578d-1e18-4c8f-bb8b-3b732b5a282d) service to localhost.localdomain/127.0.0.1:38129
[junit4] 2> 1849894 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.m.log Stopped HttpServer2$SelectChannelConnectorWithSafeStartup@localhost.localdomain:0
[junit4] 2> 1850011 INFO (SUITE-HDFSCollectionsAPITest-seed#[C2DFCCA168D328D7]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:34001 34001
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-7.x-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HDFSCollectionsAPITest_C2DFCCA168D328D7-001
[junit4] 2> Apr 01, 2018 11:07:44 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=Memory)}, docValues:{}, maxPointsInLeafNode=1077, maxMBSortInHeap=6.307783938874064, sim=RandomSimilarity(queryNorm=true): {}, locale=mn-MN, timezone=Asia/Yangon
[junit4] 2> NOTE: Linux 4.13.0-37-generic amd64/Oracle Corporation 9.0.4 (64-bit)/cpus=8,threads=1,free=279656072,total=516947968
[junit4] 2> NOTE: All tests run in this JVM: [FullSolrCloudDistribCmdsTest, SearchRateTriggerTest, TestJsonFacetRefinement, TestMinMaxOnMultiValuedField, DistributedFacetPivotWhiteBoxTest, DistributedExpandComponentTest, TestConfigSetsAPIZkFailure, SuggesterWFSTTest, TestUseDocValuesAsStored2, TestIndexSearcher, TestSQLHandler, DistributedFacetPivotLongTailTest, TestMultiValuedNumericRangeQuery, TestIndexingPerformance, TestCloudPseudoReturnFields, SolrCoreCheckLockOnStartupTest, StatsComponentTest, TestCSVResponseWriter, TestNumericTokenStream, TestSolrCloudSnapshots, TestDistribIDF, SynonymTokenizerTest, TestRetrieveFieldsOptimizer, TestSimpleTextCodec, DirectUpdateHandlerTest, TestNamedUpdateProcessors, TestCollectionsAPIViaSolrCloudCluster, TestCoreAdminApis, HLLSerializationTest, CollectionStateFormat2Test, TriLevelCompositeIdRoutingTest, TestRebalanceLeaders, MetricUtilsTest, NodeMarkersRegistrationTest, TestGroupingSearch, V2StandaloneTest, MetricsConfigTest, TestSubQueryTransformer, BlockCacheTest, SolrIndexMetricsTest, ChaosMonkeyNothingIsSafeTest, BlockJoinFacetSimpleTest, DeleteStatusTest, CollectionTooManyReplicasTest, TestUninvertingReader, TestSolrConfigHandlerConcurrent, SecurityConfHandlerTest, TestManagedResource, TestIBSimilarityFactory, TestCloudInspectUtil, TestManagedSchemaThreadSafety, AtomicUpdateProcessorFactoryTest, HttpPartitionTest, ZkShardTermsTest, TestRandomFaceting, TestStandardQParsers, TestWriterPerf, MoveReplicaTest, HdfsSyncSliceTest, TestIntervalFaceting, TestFieldCache, CdcrBidirectionalTest, TestJsonRequest, OpenExchangeRatesOrgProviderTest, UUIDFieldTest, TestSort, TestRuleBasedAuthorizationPlugin, TestBinaryField, ClassificationUpdateProcessorIntegrationTest, ResponseBuilderTest, TestReplicationHandlerBackup, BooleanFieldTest, TestGeoJSONResponseWriter, TestOnReconnectListenerSupport, TestRemoteStreaming, TestStressLucene, TestLegacyFieldCache, ZkSolrClientTest, TestUnifiedSolrHighlighter, NodeAddedTriggerTest, CursorPagingTest, TestDistributedSearch, TestImpersonationWithHadoopAuth, ShardRoutingTest, InfoHandlerTest, WrapperMergePolicyFactoryTest, EchoParamsTest, SolrCLIZkUtilsTest, ChaosMonkeyNothingIsSafeWithPullReplicasTest, CreateRoutedAliasTest, TestOmitPositions, TestManagedSynonymFilterFactory, MergeStrategyTest, TestNestedDocsSort, TestFieldTypeCollectionResource, ConfigSetsAPITest, TestLeaderInitiatedRecoveryThread, TestSolr4Spatial2, TestLRUStatsCache, TestExtendedDismaxParser, OverseerTaskQueueTest, TestDocSet, SolrPluginUtilsTest, TestSerializedLuceneMatchVersion, TestAddFieldRealTimeGet, TriggerCooldownIntegrationTest, CoreAdminOperationTest, ExitableDirectoryReaderTest, TestOverriddenPrefixQueryForCustomFieldType, SolrGraphiteReporterTest, TestCustomStream, SolrIndexConfigTest, ExecutePlanActionTest, TestSchemalessBufferedUpdates, HdfsRecoverLeaseTest, TestReRankQParserPlugin, TestJoin, BitVectorTest, TestCrossCoreJoin, TestTolerantUpdateProcessorRandomCloud, PreAnalyzedUpdateProcessorTest, TestHalfAndHalfDocValues, SpellCheckCollatorWithCollapseTest, ConnectionReuseTest, ZkNodePropsTest, DocumentAnalysisRequestHandlerTest, TestClusterStateProvider, DocExpirationUpdateProcessorFactoryTest, TestBulkSchemaAPI, ChaosMonkeySafeLeaderTest, UnloadDistributedZkTest, OpenCloseCoreStressTest, OverseerTest, TestFaceting, TestHashPartitioner, DistributedSpellCheckComponentTest, TestRealTimeGet, DistributedTermsComponentTest, TestCoreContainer, SimpleFacetsTest, SolrCoreTest, BadIndexSchemaTest, TestLazyCores, TestBadConfig, HighlighterTest, ShowFileRequestHandlerTest, DistributedQueryElevationComponentTest, TestCoreDiscovery, SolrRequestParserTest, TestTrie, TestCSVLoader, NoCacheHeaderTest, FieldMutatingUpdateProcessorTest, QueryEqualityTest, SortByFunctionTest, DocValuesMultiTest, TestSolrDeletionPolicy1, DebugComponentTest, CacheHeaderTest, LukeRequestHandlerTest, TestReversedWildcardFilterFactory, FileBasedSpellCheckerTest, XmlUpdateRequestHandlerTest, RequestHandlersTest, DocumentBuilderTest, TermVectorComponentTest, FieldAnalysisRequestHandlerTest, IndexSchemaRuntimeFieldTest, TestJmxIntegration, BinaryUpdateRequestHandlerTest, TestPHPSerializedResponseWriter, CSVRequestHandlerTest, TestComponentsName, HighlighterConfigTest, SOLR749Test, UpdateParamsTest, AlternateDirectoryTest, TestSolrIndexConfig, TestQuerySenderNoQuery, ResponseLogComponentTest, TestMergePolicyConfig, SampleTest, MinimalSchemaTest, TestElisionMultitermQuery, TestConfig, OutputWriterTest, TestFuzzyAnalyzedSuggestions, ExternalFileFieldSortTest, TestPostingsSolrHighlighter, DirectSolrConnectionTest, TestLuceneMatchVersion, TestPhraseSuggestions, TestXIncludeConfig, TestLMDirichletSimilarityFactory, TestLMJelinekMercerSimilarityFactory, TestBM25SimilarityFactory, TestFastWriter, TimeZoneUtilsTest, ResourceLoaderTest, TestFastOutputStream, ScriptEngineTest, URLClassifyProcessorTest, PluginInfoTest, TestFastLRUCache, DateMathParserTest, TestSystemIdResolver, TestSuggestSpellingConverter, SpellingQueryConverterTest, RAMDirectoryFactoryTest, TestSolrJ, TestUtils, TestDocumentBuilder, SystemInfoHandlerTest, FileUtilsTest, SolrTestCaseJ4Test, TestHighlightDedupGrouping, TestEmbeddedSolrServerAdminHandler, TestEmbeddedSolrServerConstructors, TestEmbeddedSolrServerSchemaAPI, TestJettySolrRunner, ActionThrottleTest, AddReplicaTest, CleanupOldIndexTest, DeleteNodeTest, DeleteShardTest, DistribCursorPagingTest, DistribJoinFromCollectionTest, DocValuesNotIndexedTest, ForceLeaderTest, HttpPartitionOnCommitTest, LeaderVoteWaitTimeoutTest, MissingSegmentRecoveryTest, MoveReplicaHDFSFailoverTest, PeerSyncReplicationTest, RemoteQueryErrorTest, TestCloudDeleteByQuery, TestCloudRecovery, TestPullReplica, TestSSLRandomization, TestSizeLimitedDistributedMap, TestSkipOverseerOperations, TestStressLiveNodes, TestTolerantUpdateProcessorCloud, VMParamsZkACLAndCredentialsProvidersTest, ConcurrentDeleteAndCreateCollectionTest, ShardSplitTest, AutoAddReplicasPlanActionTest, AutoScalingHandlerTest, NodeAddedTriggerIntegrationTest, ScheduledTriggerIntegrationTest, SearchRateTriggerIntegrationTest, SystemLogListenerTest, HDFSCollectionsAPITest]
[junit4] Completed [689/794 (1!)] on J0 in 123.05s, 1 test, 1 failure <<< FAILURES!
[...truncated 43153 lines...]
[repro] Jenkins log URL: https://jenkins.thetaphi.de/job/Lucene-Solr-7.x-Linux/1631/consoleText
[repro] Revision: a2fcb8c9ed4a8e7fd0c23829c089573558a987f0
[repro] Ant options: "-Dargs=-XX:+UseCompressedOops -XX:+UseParallelGC"
[repro] Repro line: ant test -Dtestcase=HDFSCollectionsAPITest -Dtests.method=testDataDirIsNotReused -Dtests.seed=C2DFCCA168D328D7 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=mn-MN -Dtests.timezone=Asia/Yangon -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 3319 lines...]
[repro] ant test-nocompile -Dtests.dups=5 -Dtests.maxfailures=5 -Dtests.class="*.HDFSCollectionsAPITest" -Dtests.showOutput=onerror "-Dargs=-XX:+UseCompressedOops -XX:+UseParallelGC" -Dtests.seed=C2DFCCA168D328D7 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=mn-MN -Dtests.timezone=Asia/Yangon -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...]