You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2017/01/17 04:00:23 UTC
[JENKINS] Lucene-Solr-Tests-6.4 - Build # 4 - Unstable
Build: https://builds.apache.org/job/Lucene-Solr-Tests-6.4/4/
2 tests failed.
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.hdfs.HdfsRecoveryZkTest
Error Message:
ObjectTracker found 1 object(s) that were not released!!! [HdfsTransactionLog] org.apache.solr.common.util.ObjectReleaseTracker$ObjectTrackerException at org.apache.solr.common.util.ObjectReleaseTracker.track(ObjectReleaseTracker.java:43) at org.apache.solr.update.HdfsTransactionLog.<init>(HdfsTransactionLog.java:130) at org.apache.solr.update.HdfsUpdateLog.init(HdfsUpdateLog.java:202) at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:137) at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:94) at org.apache.solr.update.DirectUpdateHandler2.<init>(DirectUpdateHandler2.java:102) at sun.reflect.GeneratedConstructorAccessor142.newInstance(Unknown Source) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at org.apache.solr.core.SolrCore.createInstance(SolrCore.java:753) at org.apache.solr.core.SolrCore.createUpdateHandler(SolrCore.java:815) at org.apache.solr.core.SolrCore.initUpdateHandler(SolrCore.java:1065) at org.apache.solr.core.SolrCore.<init>(SolrCore.java:930) at org.apache.solr.core.SolrCore.<init>(SolrCore.java:823) at org.apache.solr.core.CoreContainer.create(CoreContainer.java:889) at org.apache.solr.core.CoreContainer.lambda$load$3(CoreContainer.java:541) at com.codahale.metrics.InstrumentedExecutorService$InstrumentedCallable.call(InstrumentedExecutorService.java:197) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)
Stack Trace:
java.lang.AssertionError: ObjectTracker found 1 object(s) that were not released!!! [HdfsTransactionLog]
org.apache.solr.common.util.ObjectReleaseTracker$ObjectTrackerException
at org.apache.solr.common.util.ObjectReleaseTracker.track(ObjectReleaseTracker.java:43)
at org.apache.solr.update.HdfsTransactionLog.<init>(HdfsTransactionLog.java:130)
at org.apache.solr.update.HdfsUpdateLog.init(HdfsUpdateLog.java:202)
at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:137)
at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:94)
at org.apache.solr.update.DirectUpdateHandler2.<init>(DirectUpdateHandler2.java:102)
at sun.reflect.GeneratedConstructorAccessor142.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at org.apache.solr.core.SolrCore.createInstance(SolrCore.java:753)
at org.apache.solr.core.SolrCore.createUpdateHandler(SolrCore.java:815)
at org.apache.solr.core.SolrCore.initUpdateHandler(SolrCore.java:1065)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:930)
at org.apache.solr.core.SolrCore.<init>(SolrCore.java:823)
at org.apache.solr.core.CoreContainer.create(CoreContainer.java:889)
at org.apache.solr.core.CoreContainer.lambda$load$3(CoreContainer.java:541)
at com.codahale.metrics.InstrumentedExecutorService$InstrumentedCallable.call(InstrumentedExecutorService.java:197)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
at __randomizedtesting.SeedInfo.seed([3B1A7346C7B11289]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertNull(Assert.java:551)
at org.apache.solr.SolrTestCaseJ4.teardownTestCases(SolrTestCaseJ4.java:269)
at sun.reflect.GeneratedMethodAccessor56.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:870)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at java.lang.Thread.run(Thread.java:745)
FAILED: org.apache.solr.update.SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds
Error Message:
1: soft occurred too fast: 217 < (500 * 1)
Stack Trace:
java.lang.AssertionError: 1: soft occurred too fast: 217 < (500 * 1)
at __randomizedtesting.SeedInfo.seed([3B1A7346C7B11289:670FDD7F2C3353F1]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.apache.solr.update.SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds(SoftAutoCommitTest.java:328)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:907)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:957)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:811)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:462)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:916)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:802)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:852)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 11239 lines...]
[junit4] Suite: org.apache.solr.update.SoftAutoCommitTest
[junit4] 2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J1/temp/solr.update.SoftAutoCommitTest_3B1A7346C7B11289-001/init-core-data-001
[junit4] 2> 420640 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason=, value=NaN, ssl=NaN, clientAuth=NaN)
[junit4] 2> 420641 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.SolrTestCaseJ4 ####initCore
[junit4] 2> 420641 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1/lib, /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 420669 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 420689 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.s.IndexSchema [null] Schema name=test
[junit4] 2> 420767 WARN (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.s.IndexSchema [null] default search field in schema is text. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 420769 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 420778 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=30000&connTimeout=30000&retry=true
[junit4] 2> 420780 WARN (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.m.r.SolrJmxReporter No serviceUrl or agentId was configured, using first MBeanServer.
[junit4] 2> 420781 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 420781 WARN (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.m.r.SolrJmxReporter No serviceUrl or agentId was configured, using first MBeanServer.
[junit4] 2> 420784 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 420784 WARN (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.m.r.SolrJmxReporter No serviceUrl or agentId was configured, using first MBeanServer.
[junit4] 2> 420784 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 420786 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1/lib, /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 420809 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 420835 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 420913 WARN (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] default search field in schema is text. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 420915 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 420920 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1
[junit4] 2> 420920 WARN (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter No serviceUrl or agentId was configured, using first MBeanServer.
[junit4] 2> 420920 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 420920 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J1/temp/solr.update.SoftAutoCommitTest_3B1A7346C7B11289-001/init-core-data-001/]
[junit4] 2> 420921 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 420922 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogDocMergePolicy: [LogDocMergePolicy: minMergeSize=1000, mergeFactor=47, maxMergeSize=9223372036854775807, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=false, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.7770167711620019]
[junit4] 2> 420952 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 420952 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 420953 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 420953 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 420953 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=42, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0]
[junit4] 2> 420953 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@398fa723[collection1] main]
[junit4] 2> 420954 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 420960 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 420983 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 420983 INFO (searcherExecutor-1907-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 420984 INFO (searcherExecutor-1907-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 420984 INFO (searcherExecutor-1907-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 420984 INFO (searcherExecutor-1907-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 420984 INFO (searcherExecutor-1907-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 420984 INFO (searcherExecutor-1907-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 420984 INFO (searcherExecutor-1907-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 420984 INFO (searcherExecutor-1907-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 420985 INFO (searcherExecutor-1907-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 420985 INFO (searcherExecutor-1907-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@398fa723[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 420986 INFO (coreLoadExecutor-1906-thread-1) [ x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1556740043065786368
[junit4] 2> 420989 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.SolrTestCaseJ4 ####initCore end
[junit4] 2> 420991 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testSoftAndHardCommitMaxTimeRapidAdds
[junit4] 2> 420992 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ ] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1/lib, /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 421021 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 421040 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ ] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 421128 WARN (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ ] o.a.s.s.IndexSchema [collection1] default search field in schema is text. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 421131 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ ] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 421136 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ ] o.a.s.c.CoreContainer Reloading SolrCore 'collection1' using configuration from instancedir /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1
[junit4] 2> 421137 WARN (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.m.r.SolrJmxReporter No serviceUrl or agentId was configured, using first MBeanServer.
[junit4] 2> 421145 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 421146 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.m.SolrMetricManager Replacing existing reporter 'default' in registry 'solr.core.collection1': [org.apache.solr.metrics.reporters.SolrJmxReporter@7fc28e6f: domain = solr.core.collection1, service url = null, agent id = null]
[junit4] 2> 421148 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J1/temp/solr.update.SoftAutoCommitTest_3B1A7346C7B11289-001/init-core-data-001/]
[junit4] 2> 421148 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 421168 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 421168 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 421169 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@74de5ed8[collection1] main]
[junit4] 2> 421169 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 421170 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 421172 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 421173 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 421173 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 421173 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 421173 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 421173 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 421173 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 421173 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 421174 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1556740043262918656
[junit4] 2> 421174 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 421174 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 421175 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@74de5ed8[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 421176 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=49, maxMergeAtOnceExplicit=37, maxMergedSegmentMB=40.5576171875, floorSegmentMB=1.19921875, forceMergeDeletesPctAllowed=1.7563127423153913, segmentsPerTier=16.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.6431648434193712
[junit4] 2> 421177 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 421177 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@10a78ca7[collection1] main]
[junit4] 2> 421177 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@4d5b3ce8
[junit4] 2> 421179 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@10a78ca7[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 421212 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.collection1
[junit4] 2> 421214 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[5000 (1556740043302764544)]} 0 1
[junit4] 2> 421215 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[5001 (1556740043305910272)]} 0 0
[junit4] 2> 421216 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[5002 (1556740043306958848)]} 0 0
[junit4] 2> 422318 INFO (commitScheduler-1915-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 422319 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[5003 (1556740044461441024)]} 0 2
[junit4] 2> 422323 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[5004 (1556740044467732480)]} 0 0
[junit4] 2> 422333 INFO (commitScheduler-1915-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@5b6eb425[collection1] main]
[junit4] 2> 422334 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@5b6eb425[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5)))}
[junit4] 2> 422340 INFO (commitScheduler-1915-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 422341 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.SolrTestCaseJ4 ###Ending testSoftAndHardCommitMaxTimeRapidAdds
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SoftAutoCommitTest -Dtests.method=testSoftAndHardCommitMaxTimeRapidAdds -Dtests.seed=3B1A7346C7B11289 -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=th-TH -Dtests.timezone=AGT -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] FAILURE 1.35s J1 | SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds <<<
[junit4] > Throwable #1: java.lang.AssertionError: 1: soft occurred too fast: 217 < (500 * 1)
[junit4] > at __randomizedtesting.SeedInfo.seed([3B1A7346C7B11289:670FDD7F2C3353F1]:0)
[junit4] > at org.apache.solr.update.SoftAutoCommitTest.testSoftAndHardCommitMaxTimeRapidAdds(SoftAutoCommitTest.java:328)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 422344 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.SolrTestCaseJ4 ###Starting testSoftAndHardCommitMaxTimeMixedAdds
[junit4] 2> 422344 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1/lib, /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 422374 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 422400 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 422420 INFO (commitScheduler-1914-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 422420 INFO (commitScheduler-1914-thread-1) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@561cc219
[junit4] 2> 422421 INFO (commitScheduler-1914-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1a68280[collection1] main]
[junit4] 2> 422421 INFO (commitScheduler-1914-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 422422 INFO (searcherExecutor-1912-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@1a68280[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5)))}
[junit4] 2> 422481 WARN (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.IndexSchema [collection1] default search field in schema is text. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 422483 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 422489 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.CoreContainer Reloading SolrCore 'collection1' using configuration from instancedir /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1
[junit4] 2> 422489 WARN (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.m.r.SolrJmxReporter No serviceUrl or agentId was configured, using first MBeanServer.
[junit4] 2> 422496 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 422496 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J1/temp/solr.update.SoftAutoCommitTest_3B1A7346C7B11289-001/init-core-data-001/]
[junit4] 2> 422496 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 422515 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 422515 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 422515 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@32c1e795[collection1] main]
[junit4] 2> 422515 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 422516 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 422518 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 422532 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.MockRandomMergePolicy: org.apache.lucene.index.MockRandomMergePolicy@5f3a131
[junit4] 2> 422533 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 422533 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 422533 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 422533 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 422533 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 422534 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 422534 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 422535 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 422535 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 422535 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 422536 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@32c1e795[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5)))}
[junit4] 2> 422537 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@18c72267[collection1] main]
[junit4] 2> 422537 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@6c9d15b2
[junit4] 2> 422539 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@18c72267[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5)))}
[junit4] 2> 422585 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.collection1
[junit4] 2> 422592 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[529 (1556740044745605120)]} 0 3
[junit4] 2> 423092 INFO (commitScheduler-1919-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 423097 INFO (commitScheduler-1919-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@51c61ca7[collection1] main]
[junit4] 2> 423101 INFO (commitScheduler-1919-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 423102 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@51c61ca7[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5) Uninverting(_1(6.4.0):C1)))}
[junit4] 2> 423103 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[530 (1556740045284573184)]} 0 0
[junit4] 2> 423603 INFO (commitScheduler-1919-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 423605 INFO (commitScheduler-1919-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6d15f308[collection1] main]
[junit4] 2> 423605 INFO (commitScheduler-1919-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 423606 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@6d15f308[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5) Uninverting(_1(6.4.0):C1) Uninverting(_2(6.4.0):C1)))}
[junit4] 2> 423792 INFO (commitScheduler-1918-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 423792 INFO (commitScheduler-1918-thread-1) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@1b415335
[junit4] 2> 423793 INFO (commitScheduler-1918-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@3c08633e[collection1] main]
[junit4] 2> 423793 INFO (commitScheduler-1918-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 423794 INFO (searcherExecutor-1916-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@3c08633e[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5) Uninverting(_1(6.4.0):C1) Uninverting(_2(6.4.0):C1)))}
[junit4] 2> 426993 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeMixedAdds-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.SolrTestCaseJ4 ###Ending testSoftAndHardCommitMaxTimeMixedAdds
[junit4] 2> 426995 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.SolrTestCaseJ4 ###Starting testSoftAndHardCommitMaxTimeDelete
[junit4] 2> 426995 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1/lib, /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 427017 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 427035 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 427102 WARN (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.IndexSchema [collection1] default search field in schema is text. WARNING: Deprecated, please use 'df' on request instead.
[junit4] 2> 427104 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 427109 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.CoreContainer Reloading SolrCore 'collection1' using configuration from instancedir /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1
[junit4] 2> 427109 WARN (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.m.r.SolrJmxReporter No serviceUrl or agentId was configured, using first MBeanServer.
[junit4] 2> 427115 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 427115 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/core/src/test-files/solr/collection1], dataDir=[/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J1/temp/solr.update.SoftAutoCommitTest_3B1A7346C7B11289-001/init-core-data-001/]
[junit4] 2> 427115 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.JmxMonitoredMap JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@75dafa90
[junit4] 2> 427134 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 427134 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 427135 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@769f1a80[collection1] main]
[junit4] 2> 427135 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 427135 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 427140 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 427143 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 427143 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 427144 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 427144 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 427144 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 427144 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 427144 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 427144 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 427145 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 427145 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=48, maxMergeAtOnceExplicit=45, maxMergedSegmentMB=34.1455078125, floorSegmentMB=1.07421875, forceMergeDeletesPctAllowed=5.991428901292984, segmentsPerTier=37.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.26744620749219933
[junit4] 2> 427145 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@769f1a80[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5) Uninverting(_1(6.4.0):C1) Uninverting(_2(6.4.0):C1)))}
[junit4] 2> 427148 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
[junit4] 2> 427150 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@2dfb4dd3[collection1] main]
[junit4] 2> 427151 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@2dfb4dd3[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5) Uninverting(_1(6.4.0):C1) Uninverting(_2(6.4.0):C1)))}
[junit4] 2> 427151 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@74390169
[junit4] 2> 427193 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.collection1
[junit4] 2> 427197 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[529 (1556740049577443328)]} 0 1
[junit4] 2> 427197 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 427197 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@69e8a796
[junit4] 2> 427200 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@6e9d2f52[collection1] main]
[junit4] 2> 427200 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 427201 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@6e9d2f52[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5) Uninverting(_2(6.4.0):C1) Uninverting(_3(6.4.0):C1)))}
[junit4] 2> 427201 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{commit=} 0 3
[junit4] 2> 427202 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{delete=[529 (-1556740049583734784)]} 0 0
[junit4] 2> 427703 INFO (commitScheduler-1923-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 427704 INFO (commitScheduler-1923-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@52020141[collection1] main]
[junit4] 2> 427705 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@52020141[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5) Uninverting(_2(6.4.0):C1)))}
[junit4] 2> 427706 INFO (commitScheduler-1923-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 427706 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.u.p.LogUpdateProcessorFactory [collection1] webapp=null path=null params={}{add=[550 (1556740050112217088)]} 0 0
[junit4] 2> 428206 INFO (commitScheduler-1923-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 428208 INFO (commitScheduler-1923-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1b78341e[collection1] main]
[junit4] 2> 428208 INFO (commitScheduler-1923-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 428209 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@1b78341e[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5) Uninverting(_2(6.4.0):C1) Uninverting(_4(6.4.0):C1)))}
[junit4] 2> 428403 INFO (commitScheduler-1922-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4] 2> 428403 INFO (commitScheduler-1922-thread-1) [ x:collection1] o.a.s.u.SolrIndexWriter Calling setCommitData with IW:org.apache.solr.update.SolrIndexWriter@69e8a796
[junit4] 2> 428403 INFO (commitScheduler-1922-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@e097522[collection1] main]
[junit4] 2> 428403 INFO (commitScheduler-1922-thread-1) [ x:collection1] o.a.s.u.DirectUpdateHandler2 end_commit_flush
[junit4] 2> 428404 INFO (searcherExecutor-1920-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@e097522[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(6.4.0):C5) Uninverting(_2(6.4.0):C1) Uninverting(_4(6.4.0):C1)))}
[junit4] 2> 430403 INFO (TEST-SoftAutoCommitTest.testSoftAndHardCommitMaxTimeDelete-seed#[3B1A7346C7B11289]) [ x:collection1] o.a.s.SolrTestCaseJ4 ###Ending testSoftAndHardCommitMaxTimeDelete
[junit4] 2> 430403 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ x:collection1] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> 430403 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ x:collection1] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1961857621
[junit4] 2> 430404 INFO (coreCloseExecutor-1924-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@42c8b01b
[junit4] 2> 430429 INFO (coreCloseExecutor-1924-thread-1-processing-x:collection1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.core.collection1
[junit4] 2> 430429 INFO (SUITE-SoftAutoCommitTest-seed#[3B1A7346C7B11289]-worker) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for: solr.node
[junit4] 2> NOTE: leaving temporary files on disk at: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J1/temp/solr.update.SoftAutoCommitTest_3B1A7346C7B11289-001
[junit4] 2> NOTE: test params are: codec=CheapBastard, sim=RandomSimilarity(queryNorm=true,coord=yes): {}, locale=th-TH, timezone=AGT
[junit4] 2> NOTE: Linux 3.13.0-85-generic amd64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=4,threads=1,free=324354048,total=531628032
[junit4] 2> NOTE: All tests run in this JVM: [HdfsTlogReplayBufferedWhileIndexingTest, TestCSVResponseWriter, DeleteStatusTest, SolrIndexConfigTest, TestLuceneMatchVersion, CSVRequestHandlerTest, TestManagedStopFilterFactory, SuggesterFSTTest, LeaderElectionContextKeyTest, DeleteNodeTest, RecoveryAfterSoftCommitTest, TestCoreContainer, BigEndianAscendingWordSerializerTest, DocumentBuilderTest, SortByFunctionTest, BasicFunctionalityTest, TestJavabinTupleStreamParser, HdfsNNFailoverTest, TestSchemaSimilarityResource, TestSweetSpotSimilarityFactory, TestCollationFieldDocValues, TestComplexPhraseQParserPlugin, HighlighterMaxOffsetTest, TestSuggestSpellingConverter, TestDefaultSearchFieldResource, CollectionsAPIAsyncDistributedZkTest, TestConfigSetsAPIExclusivity, OverseerCollectionConfigSetProcessorTest, EchoParamsTest, TestQuerySenderListener, TestConfigSetProperties, OpenCloseCoreStressTest, DistributedFacetPivotLongTailTest, WordBreakSolrSpellCheckerTest, IndexSchemaTest, MultiTermTest, TestSolrCoreSnapshots, TestExportWriter, AnalyticsQueryTest, TestQueryTypes, SparseHLLTest, TestRequestForwarding, TestObjectReleaseTracker, ConvertedLegacyTest, BasicAuthIntegrationTest, TestFieldCacheReopen, SolrInfoMBeanTest, TestReqParamsAPI, TestXmlQParserPlugin, DistanceFunctionTest, FileUtilsTest, TestTolerantUpdateProcessorRandomCloud, TestFreeTextSuggestions, TestUpdate, TestSQLHandlerNonCloud, TestWordDelimiterFilterFactory, ZkStateWriterTest, SimpleMLTQParserTest, DateMathParserTest, TestCustomStream, SampleTest, LoggingHandlerTest, TestStressUserVersions, CachingDirectoryFactoryTest, TestPKIAuthenticationPlugin, DocValuesMissingTest, TestManagedSchemaThreadSafety, ShardRoutingTest, SliceStateTest, TestSubQueryTransformer, TestAnalyzeInfixSuggestions, TestHashPartitioner, TermsComponentTest, TestSolrCloudWithDelegationTokens, VMParamsZkACLAndCredentialsProvidersTest, SolrGraphiteReporterTest, MultiThreadedOCPTest, SoftAutoCommitTest]
[junit4] Completed [159/680 (1!)] on J1 in 9.82s, 3 tests, 1 failure <<< FAILURES!
[...truncated 1294 lines...]
[junit4] Suite: org.apache.solr.cloud.hdfs.HdfsRecoveryZkTest
[junit4] 2> Creating dataDir: /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_3B1A7346C7B11289-001/init-core-data-001
[junit4] 2> 1743803 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 1743804 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_3B1A7346C7B11289-001/tempDir-001
[junit4] 2> 1743804 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 1743804 INFO (Thread-3050) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 1743804 INFO (Thread-3050) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 1743904 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:58059
[junit4] 2> 1743915 INFO (jetty-launcher-8841-thread-1) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1743915 INFO (jetty-launcher-8841-thread-2) [ ] o.e.j.s.Server jetty-9.3.14.v20161028
[junit4] 2> 1743916 INFO (jetty-launcher-8841-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@5adc6760{/solr,null,AVAILABLE}
[junit4] 2> 1743916 INFO (jetty-launcher-8841-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@28f427cf{/solr,null,AVAILABLE}
[junit4] 2> 1743918 INFO (jetty-launcher-8841-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@2af50d3c{SSL,[ssl, http/1.1]}{127.0.0.1:34360}
[junit4] 2> 1743918 INFO (jetty-launcher-8841-thread-2) [ ] o.e.j.s.Server Started @1747951ms
[junit4] 2> 1743918 INFO (jetty-launcher-8841-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=34360}
[junit4] 2> 1743920 INFO (jetty-launcher-8841-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@29295daf{SSL,[ssl, http/1.1]}{127.0.0.1:52424}
[junit4] 2> 1743921 ERROR (jetty-launcher-8841-thread-2) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1743921 INFO (jetty-launcher-8841-thread-1) [ ] o.e.j.s.Server Started @1747954ms
[junit4] 2> 1743921 INFO (jetty-launcher-8841-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 1743921 INFO (jetty-launcher-8841-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=52424}
[junit4] 2> 1743921 INFO (jetty-launcher-8841-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1743921 INFO (jetty-launcher-8841-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1743921 INFO (jetty-launcher-8841-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-01-17T03:38:39.394Z
[junit4] 2> 1743921 ERROR (jetty-launcher-8841-thread-1) [ ] o.a.s.s.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 1743921 INFO (jetty-launcher-8841-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr™ version 6.4.0
[junit4] 2> 1743921 INFO (jetty-launcher-8841-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 1743921 INFO (jetty-launcher-8841-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 1743921 INFO (jetty-launcher-8841-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2017-01-17T03:38:39.394Z
[junit4] 2> 1743923 INFO (jetty-launcher-8841-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1743926 INFO (jetty-launcher-8841-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 1743930 INFO (jetty-launcher-8841-thread-1) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1743931 INFO (jetty-launcher-8841-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:58059/solr
[junit4] 2> 1743932 INFO (jetty-launcher-8841-thread-2) [ ] o.a.s.u.UpdateShardHandler Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=true
[junit4] 2> 1743932 INFO (jetty-launcher-8841-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:58059/solr
[junit4] 2> 1743955 INFO (jetty-launcher-8841-thread-1) [n:127.0.0.1:52424_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:52424_solr
[junit4] 2> 1743956 INFO (jetty-launcher-8841-thread-2) [n:127.0.0.1:34360_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34360_solr
[junit4] 2> 1743956 INFO (jetty-launcher-8841-thread-1) [n:127.0.0.1:52424_solr ] o.a.s.c.Overseer Overseer (id=97296339388203014-127.0.0.1:52424_solr-n_0000000000) starting
[junit4] 2> 1743965 INFO (zkCallback-8851-thread-1-processing-n:127.0.0.1:34360_solr) [n:127.0.0.1:34360_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1743970 INFO (zkCallback-8852-thread-1-processing-n:127.0.0.1:52424_solr) [n:127.0.0.1:52424_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 1743975 INFO (jetty-launcher-8841-thread-1) [n:127.0.0.1:52424_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52424_solr
[junit4] 2> 1743976 INFO (zkCallback-8851-thread-1-processing-n:127.0.0.1:34360_solr) [n:127.0.0.1:34360_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1743980 INFO (zkCallback-8852-thread-1-processing-n:127.0.0.1:52424_solr) [n:127.0.0.1:52424_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 1744003 INFO (jetty-launcher-8841-thread-2) [n:127.0.0.1:34360_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_3B1A7346C7B11289-001/tempDir-001/node2/.
[junit4] 2> 1744126 INFO (jetty-launcher-8841-thread-1) [n:127.0.0.1:52424_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_3B1A7346C7B11289-001/tempDir-001/node1/.
[junit4] 2> 1744436 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 1744437 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:58059/solr ready
[junit4] 1> Formatting using clusterid: testClusterID
[junit4] 2> 1744475 WARN (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.h.m.i.MetricsConfig Cannot locate configuration: tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
[junit4] 2> 1744485 WARN (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 1744487 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 1744499 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.m.log Extract jar:file:/x1/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.2-tests.jar!/webapps/hdfs to ./temp/Jetty_localhost_54735_hdfs____.yvfk3g/webapp
[junit4] 2> 1744890 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:54735
[junit4] 2> 1744975 WARN (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 1744976 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 1744985 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.m.log Extract jar:file:/x1/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.2-tests.jar!/webapps/datanode to ./temp/Jetty_localhost_58208_datanode____.kza3j6/webapp
[junit4] 2> 1745346 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:58208
[junit4] 2> 1745415 WARN (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.h.h.HttpRequestLog Jetty request log can only be enabled using Log4j
[junit4] 2> 1745416 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.m.log jetty-6.1.26
[junit4] 2> 1745425 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.m.log Extract jar:file:/x1/jenkins/.ivy2/cache/org.apache.hadoop/hadoop-hdfs/tests/hadoop-hdfs-2.7.2-tests.jar!/webapps/datanode to ./temp/Jetty_localhost_33255_datanode____k98uzd/webapp
[junit4] 2> 1745484 INFO (IPC Server handler 0 on 49933) [ ] BlockStateChange BLOCK* processReport: from storage DS-aa73f4d0-0f61-4936-a4b7-f02fbfda73c3 node DatanodeRegistration(127.0.0.1:57506, datanodeUuid=bb140a17-009a-4c27-927f-a84510c4b2d2, infoPort=51186, infoSecurePort=0, ipcPort=56596, storageInfo=lv=-56;cid=testClusterID;nsid=1298692882;c=0), blocks: 0, hasStaleStorage: true, processing time: 0 msecs
[junit4] 2> 1745484 INFO (IPC Server handler 0 on 49933) [ ] BlockStateChange BLOCK* processReport: from storage DS-eab25057-f72c-4c6e-a597-ffee4a3c9271 node DatanodeRegistration(127.0.0.1:57506, datanodeUuid=bb140a17-009a-4c27-927f-a84510c4b2d2, infoPort=51186, infoSecurePort=0, ipcPort=56596, storageInfo=lv=-56;cid=testClusterID;nsid=1298692882;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
[junit4] 2> 1745808 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.m.log Started HttpServer2$SelectChannelConnectorWithSafeStartup@localhost:33255
[junit4] 2> 1745891 INFO (IPC Server handler 8 on 49933) [ ] BlockStateChange BLOCK* processReport: from storage DS-1387aea1-326a-41d7-8073-79841c6179e4 node DatanodeRegistration(127.0.0.1:44033, datanodeUuid=da1098dd-21b7-439b-a3ff-803d9942fd3f, infoPort=37390, infoSecurePort=0, ipcPort=53909, storageInfo=lv=-56;cid=testClusterID;nsid=1298692882;c=0), blocks: 0, hasStaleStorage: true, processing time: 0 msecs
[junit4] 2> 1745891 INFO (IPC Server handler 8 on 49933) [ ] BlockStateChange BLOCK* processReport: from storage DS-6f3db48b-7d52-4052-974e-bc0cc24c6cf0 node DatanodeRegistration(127.0.0.1:44033, datanodeUuid=da1098dd-21b7-439b-a3ff-803d9942fd3f, infoPort=37390, infoSecurePort=0, ipcPort=53909, storageInfo=lv=-56;cid=testClusterID;nsid=1298692882;c=0), blocks: 0, hasStaleStorage: false, processing time: 0 msecs
[junit4] 2> 1745999 INFO (TEST-HdfsRecoveryZkTest.test-seed#[3B1A7346C7B11289]) [ ] o.a.s.SolrTestCaseJ4 ###Starting test
[junit4] 2> 1746057 INFO (qtp2087464262-18132) [n:127.0.0.1:34360_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params replicationFactor=2&collection.configName=conf&maxShardsPerNode=1&name=recoverytest&action=CREATE&numShards=1&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 1746059 INFO (OverseerThreadFactory-5456-thread-1-processing-n:127.0.0.1:52424_solr) [n:127.0.0.1:52424_solr ] o.a.s.c.CreateCollectionCmd Create collection recoverytest
[junit4] 2> 1746176 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=recoverytest_shard1_replica1&action=CREATE&numShards=1&collection=recoverytest&shard=shard1&wt=javabin&version=2
[junit4] 2> 1746221 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&collection.configName=conf&newCollection=true&name=recoverytest_shard1_replica2&action=CREATE&numShards=1&collection=recoverytest&shard=shard1&wt=javabin&version=2
[junit4] 2> 1746324 INFO (zkCallback-8852-thread-2-processing-n:127.0.0.1:52424_solr) [n:127.0.0.1:52424_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1746324 INFO (zkCallback-8851-thread-1-processing-n:127.0.0.1:34360_solr) [n:127.0.0.1:34360_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1747183 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 1747190 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.IndexSchema [recoverytest_shard1_replica1] Schema name=minimal
[junit4] 2> 1747192 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 1747193 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.CoreContainer Creating SolrCore 'recoverytest_shard1_replica1' using configuration from collection recoverytest
[junit4] 2> 1747203 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://localhost:49933/data
[junit4] 2> 1747203 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 1747203 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.SolrCore [[recoverytest_shard1_replica1] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_3B1A7346C7B11289-001/tempDir-001/node2/recoverytest_shard1_replica1], dataDir=[hdfs://localhost:49933/data/recoverytest/core_node1/data/]
[junit4] 2> 1747203 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:49933/data/recoverytest/core_node1/data/snapshot_metadata
[junit4] 2> 1747218 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 1747218 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
[junit4] 2> 1747218 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Creating new single instance HDFS BlockCache
[junit4] 2> 1747227 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.SolrConfig Using Lucene MatchVersion: 6.4.0
[junit4] 2> 1747235 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.IndexSchema [recoverytest_shard1_replica2] Schema name=minimal
[junit4] 2> 1747238 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.IndexSchema Loaded schema minimal/1.1 with uniqueid field id
[junit4] 2> 1747239 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.CoreContainer Creating SolrCore 'recoverytest_shard1_replica2' using configuration from collection recoverytest
[junit4] 2> 1747239 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory solr.hdfs.home=hdfs://localhost:49933/data
[junit4] 2> 1747239 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Solr Kerberos Authentication disabled
[junit4] 2> 1747239 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.SolrCore [[recoverytest_shard1_replica2] ] Opening new SolrCore at [/x1/jenkins/jenkins-slave/workspace/Lucene-Solr-Tests-6.4/solr/build/solr-core/test/J0/temp/solr.cloud.hdfs.HdfsRecoveryZkTest_3B1A7346C7B11289-001/tempDir-001/node1/recoverytest_shard1_replica2], dataDir=[hdfs://localhost:49933/data/recoverytest/core_node2/data/]
[junit4] 2> 1747240 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:49933/data/recoverytest/core_node2/data/snapshot_metadata
[junit4] 2> 1747246 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 1747246 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
[junit4] 2> 1747246 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Creating new single instance HDFS BlockCache
[junit4] 2> 1747288 WARN (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.h.HdfsDirectory The NameNode is in SafeMode - Solr will wait 5 seconds and try again.
[junit4] 2> 1747288 WARN (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.h.HdfsDirectory The NameNode is in SafeMode - Solr will wait 5 seconds and try again.
[junit4] 2> 1752290 WARN (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.h.HdfsDirectory The NameNode is in SafeMode - Solr will wait 5 seconds and try again.
[junit4] 2> 1752290 WARN (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.h.HdfsDirectory The NameNode is in SafeMode - Solr will wait 5 seconds and try again.
[junit4] 2> 1757472 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 1757472 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 1757478 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:49933/data/recoverytest/core_node1/data
[junit4] 2> 1757482 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:49933/data/recoverytest/core_node2/data
[junit4] 2> 1757501 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:49933/data/recoverytest/core_node1/data/index
[junit4] 2> 1757508 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory creating directory factory for path hdfs://localhost:49933/data/recoverytest/core_node2/data/index
[junit4] 2> 1757508 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 1757508 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
[junit4] 2> 1757508 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.HdfsDirectoryFactory Creating new single instance HDFS BlockCache
[junit4] 2> 1757514 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Number of slabs of block cache [1] with direct memory allocation set to [true]
[junit4] 2> 1757514 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Block cache target memory usage, slab size of [16777216] will allocate [1] slabs and use ~[16777216] bytes
[junit4] 2> 1757514 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.c.HdfsDirectoryFactory Creating new single instance HDFS BlockCache
[junit4] 2> 1757532 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 1757540 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.b.BlockDirectory Block cache on write is disabled
[junit4] 2> 1757590 INFO (IPC Server handler 4 on 49933) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:44033 is added to blk_1073741825_1001{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-aa73f4d0-0f61-4936-a4b7-f02fbfda73c3:NORMAL:127.0.0.1:57506|RBW], ReplicaUC[[DISK]DS-1387aea1-326a-41d7-8073-79841c6179e4:NORMAL:127.0.0.1:44033|FINALIZED]]} size 0
[junit4] 2> 1757590 INFO (IPC Server handler 4 on 49933) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:57506 is added to blk_1073741825_1001{UCState=UNDER_CONSTRUCTION, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-aa73f4d0-0f61-4936-a4b7-f02fbfda73c3:NORMAL:127.0.0.1:57506|RBW], ReplicaUC[[DISK]DS-1387aea1-326a-41d7-8073-79841c6179e4:NORMAL:127.0.0.1:44033|FINALIZED]]} size 0
[junit4] 2> 1757629 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
[junit4] 2> 1757630 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1757630 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=3
[junit4] 2> 1757643 INFO (IPC Server handler 5 on 49933) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:44033 is added to blk_1073741826_1002{UCState=COMMITTED, truncateBlock=null, primaryNodeIndex=-1, replicas=[ReplicaUC[[DISK]DS-eab25057-f72c-4c6e-a597-ffee4a3c9271:NORMAL:127.0.0.1:57506|RBW], ReplicaUC[[DISK]DS-6f3db48b-7d52-4052-974e-bc0cc24c6cf0:NORMAL:127.0.0.1:44033|RBW]]} size 71
[junit4] 2> 1757647 INFO (IPC Server handler 8 on 49933) [ ] BlockStateChange BLOCK* addStoredBlock: blockMap updated: 127.0.0.1:57506 is added to blk_1073741826_1002 size 71
[junit4] 2> 1757660 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1757660 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1757688 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1a25a5f0[recoverytest_shard1_replica1] main]
[junit4] 2> 1757688 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/conf
[junit4] 2> 1757688 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf
[junit4] 2> 1757694 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000
[junit4] 2> 1757695 INFO (searcherExecutor-5461-thread-1-processing-n:127.0.0.1:34360_solr x:recoverytest_shard1_replica1 s:shard1 c:recoverytest) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.SolrCore [recoverytest_shard1_replica1] Registered new searcher Searcher@1a25a5f0[recoverytest_shard1_replica1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 1757695 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1556741444775968768
[junit4] 2> 1757700 INFO (qtp2087464262-18123) [n:127.0.0.1:34360_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica1] o.a.s.c.ShardLeaderElectionContext Waiting until we see more replicas up for shard shard1: total=2 found=1 timeoutin=9999ms
[junit4] 2> 1757701 INFO (zkCallback-8852-thread-1-processing-n:127.0.0.1:52424_solr) [n:127.0.0.1:52424_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1757701 INFO (zkCallback-8851-thread-1-processing-n:127.0.0.1:34360_solr) [n:127.0.0.1:34360_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/recoverytest/state.json] for collection [recoverytest] has occurred - updating... (live nodes size: [2])
[junit4] 2> 1758062 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.HdfsUpdateLog
[junit4] 2> 1758062 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir=null defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 1758062 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.u.HdfsUpdateLog Initializing HdfsUpdateLog: tlogDfsReplication=3
[junit4] 2> 1758071 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 1758071 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 1758088 INFO (qtp1019677571-18135) [n:127.0.0.1:52424_solr c:recoverytest s:shard1 x:recoverytest_shard1_replica2] o.a.s.s.SolrIndex
[...truncated too long message...]
e.hadoop.hdfs.server.namenode.metrics.NameNodeMetrics.shutdown(NameNodeMetrics.java:171)
[junit4] 2> at org.apache.hadoop.hdfs.server.namenode.NameNode.stop(NameNode.java:872)
[junit4] 2> at org.apache.hadoop.hdfs.MiniDFSCluster.shutdown(MiniDFSCluster.java:1726)
[junit4] 2> at org.apache.hadoop.hdfs.MiniDFSCluster.shutdown(MiniDFSCluster.java:1705)
[junit4] 2> at org.apache.solr.cloud.hdfs.HdfsTestUtil.teardownClass(HdfsTestUtil.java:198)
[junit4] 2> at org.apache.solr.cloud.hdfs.HdfsRecoveryZkTest.teardownClass(HdfsRecoveryZkTest.java:51)
[junit4] 2> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4] 2> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[junit4] 2> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4] 2> at java.lang.reflect.Method.invoke(Method.java:498)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1713)
[junit4] 2> at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:870)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
[junit4] 2> at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
[junit4] 2> at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
[junit4] 2> at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
[junit4] 2> at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
[junit4] 2> at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
[junit4] 2> at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:367)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> Caused by: java.lang.NullPointerException
[junit4] 2> at org.apache.hadoop.hdfs.server.blockmanagement.BlocksMap.size(BlocksMap.java:203)
[junit4] 2> at org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.getTotalBlocks(BlockManager.java:3370)
[junit4] 2> at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getBlocksTotal(FSNamesystem.java:5729)
[junit4] 2> ... 54 more
[junit4] 2> 1776080 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:58059 58059
[junit4] 2> 1776082 INFO (SUITE-HdfsRecoveryZkTest-seed#[3B1A7346C7B11289]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene62): {rnd_b=PostingsFormat(name=Direct), _version_=Lucene50(blocksize=128), a_t=FST50, a_i=PostingsFormat(name=Direct), id=PostingsFormat(name=Direct)}, docValues:{}, maxPointsInLeafNode=1856, maxMBSortInHeap=7.767516531261604, sim=RandomSimilarity(queryNorm=true,coord=no): {}, locale=hu, timezone=US/East-Indiana
[junit4] 2> NOTE: Linux 3.13.0-85-generic amd64/Oracle Corporation 1.8.0_102 (64-bit)/cpus=4,threads=2,free=327487800,total=512229376
[junit4] 2> NOTE: All tests run in this JVM: [DirectoryFactoryTest, TestDistribIDF, DistributedFacetPivotSmallTest, MBeansHandlerTest, TestLazyCores, HdfsDirectoryTest, TestSizeLimitedDistributedMap, SolrGangliaReporterTest, TestDocumentBuilder, TestAddFieldRealTimeGet, TestRemoteStreaming, TestSolrCloudSnapshots, TestFieldCacheWithThreads, TestImplicitCoreProperties, TestJmxIntegration, TestPHPSerializedResponseWriter, ConcurrentDeleteAndCreateCollectionTest, ConjunctionSolrSpellCheckerTest, AnalysisAfterCoreReloadTest, QueryEqualityTest, SolrSlf4jReporterTest, TestScoreJoinQPNoScore, TestPerFieldSimilarityWithDefaultOverride, PeerSyncTest, BasicZkTest, ExternalFileFieldSortTest, TestIBSimilarityFactory, TestFieldTypeCollectionResource, CreateCollectionCleanupTest, CacheHeaderTest, PeerSyncWithIndexFingerprintCachingTest, HighlighterConfigTest, ShardSplitTest, TestRangeQuery, TestCSVLoader, TestSolrDeletionPolicy2, CursorPagingTest, TestNamedUpdateProcessors, UUIDFieldTest, RollingRestartTest, TestBlobHandler, TestFunctionQuery, DeleteShardTest, TestSQLHandler, LeaderElectionIntegrationTest, ZkNodePropsTest, XsltUpdateRequestHandlerTest, DistributedSpellCheckComponentTest, HdfsWriteToMultipleCollectionsTest, SecurityConfHandlerTest, PolyFieldTest, TestDistributedSearch, TestReplicationHandler, ClusterStateTest, FileBasedSpellCheckerTest, TestUniqueKeyFieldResource, TestCloudRecovery, OutputWriterTest, TestSolr4Spatial2, DistanceUnitsTest, TestRandomFaceting, CdcrReplicationDistributedZkTest, TestNumericTerms64, TestComplexPhraseLeadingWildcard, HdfsThreadLeakTest, TestSlowCompositeReaderWrapper, DistribDocExpirationUpdateProcessorTest, TestSolrCLIRunExample, TestJsonFacets, HdfsBasicDistributedZkTest, TestIntervalFaceting, TestCopyFieldCollectionResource, TestSchemaResource, SimpleCollectionCreateDeleteTest, TestNRTOpen, DocExpirationUpdateProcessorFactoryTest, TestFoldingMultitermQuery, ClassificationUpdateProcessorIntegrationTest, ReplicaListTransformerTest, RuleEngineTest, ReplaceNodeTest, ManagedSchemaRoundRobinCloudTest, SuggestComponentContextFilterQueryTest, TestConfigSetImmutable, TestCryptoKeys, CollectionTooManyReplicasTest, TestDynamicFieldResource, BlockCacheTest, TestDFISimilarityFactory, UniqFieldsUpdateProcessorFactoryTest, CoreMergeIndexesAdminHandlerTest, DateRangeFieldTest, TestBadConfig, SignatureUpdateProcessorFactoryTest, CloudExitableDirectoryReaderTest, AnalyticsMergeStrategyTest, CurrencyFieldOpenExchangeTest, TestSubQueryTransformerDistrib, SolrRequestParserTest, CdcrVersionReplicationTest, TestManagedSchemaAPI, TestComponentsName, TestMissingGroups, TestBulkSchemaConcurrent, TestAtomicUpdateErrorCases, QueryElevationComponentTest, TestPseudoReturnFields, TestCloudSchemaless, TestQuerySenderNoQuery, MergeStrategyTest, TlogReplayBufferedWhileIndexingTest, TriLevelCompositeIdRoutingTest, HdfsRecoveryZkTest]
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=HdfsRecoveryZkTest -Dtests.seed=3B1A7346C7B11289 -Dtests.multiplier=2 -Dtests.slow=true -Dtests.locale=hu -Dtests.timezone=US/East-Indiana -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] ERROR 0.00s J0 | HdfsRecoveryZkTest (suite) <<<
[junit4] > Throwable #1: java.lang.AssertionError: ObjectTracker found 1 object(s) that were not released!!! [HdfsTransactionLog]
[junit4] > org.apache.solr.common.util.ObjectReleaseTracker$ObjectTrackerException
[junit4] > at org.apache.solr.common.util.ObjectReleaseTracker.track(ObjectReleaseTracker.java:43)
[junit4] > at org.apache.solr.update.HdfsTransactionLog.<init>(HdfsTransactionLog.java:130)
[junit4] > at org.apache.solr.update.HdfsUpdateLog.init(HdfsUpdateLog.java:202)
[junit4] > at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:137)
[junit4] > at org.apache.solr.update.UpdateHandler.<init>(UpdateHandler.java:94)
[junit4] > at org.apache.solr.update.DirectUpdateHandler2.<init>(DirectUpdateHandler2.java:102)
[junit4] > at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
[junit4] > at org.apache.solr.core.SolrCore.createInstance(SolrCore.java:753)
[junit4] > at org.apache.solr.core.SolrCore.createUpdateHandler(SolrCore.java:815)
[junit4] > at org.apache.solr.core.SolrCore.initUpdateHandler(SolrCore.java:1065)
[junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:930)
[junit4] > at org.apache.solr.core.SolrCore.<init>(SolrCore.java:823)
[junit4] > at org.apache.solr.core.CoreContainer.create(CoreContainer.java:889)
[junit4] > at org.apache.solr.core.CoreContainer.lambda$load$3(CoreContainer.java:541)
[junit4] > at com.codahale.metrics.InstrumentedExecutorService$InstrumentedCallable.call(InstrumentedExecutorService.java:197)
[junit4] > at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] > at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:229)
[junit4] > at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit4] > at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] > at __randomizedtesting.SeedInfo.seed([3B1A7346C7B11289]:0)
[junit4] > at org.apache.solr.SolrTestCaseJ4.teardownTestCases(SolrTestCaseJ4.java:269)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] Completed [555/680 (2!)] on J0 in 63.34s, 1 test, 1 failure <<< FAILURES!
[...truncated 62901 lines...]