You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2018/09/03 13:12:26 UTC
[JENKINS] Lucene-Solr-master-Linux (64bit/jdk-9.0.4) - Build #
22794 - Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-master-Linux/22794/
Java: 64bit/jdk-9.0.4 -XX:+UseCompressedOops -XX:+UseParallelGC
2 tests failed.
FAILED: org.apache.solr.handler.RequestLoggingTest.testLogBeforeExecuteWithCoreLogger
Error Message:
Stack Trace:
java.lang.AssertionError
at __randomizedtesting.SeedInfo.seed([DC7D7E5F20D34432:10FB7ED1DE1A2FA4]:0)
at org.junit.Assert.fail(Assert.java:92)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertTrue(Assert.java:54)
at org.apache.solr.handler.RequestLoggingTest.testLogBeforeExecute(RequestLoggingTest.java:88)
at org.apache.solr.handler.RequestLoggingTest.testLogBeforeExecuteWithCoreLogger(RequestLoggingTest.java:65)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.base/java.lang.Thread.run(Thread.java:844)
FAILED: org.apache.solr.handler.RequestLoggingTest.testLogBeforeExecuteWithRequestLogger
Error Message:
Stack Trace:
java.lang.AssertionError
at __randomizedtesting.SeedInfo.seed([DC7D7E5F20D34432:6D145E508D25FC7C]:0)
at org.junit.Assert.fail(Assert.java:92)
at org.junit.Assert.assertTrue(Assert.java:43)
at org.junit.Assert.assertTrue(Assert.java:54)
at org.apache.solr.handler.RequestLoggingTest.testLogBeforeExecute(RequestLoggingTest.java:88)
at org.apache.solr.handler.RequestLoggingTest.testLogBeforeExecuteWithRequestLogger(RequestLoggingTest.java:71)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:564)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.base/java.lang.Thread.run(Thread.java:844)
Build Log:
[...truncated 14502 lines...]
[junit4] Suite: org.apache.solr.handler.RequestLoggingTest
[junit4] 2> 2399499 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.handler.RequestLoggingTest_DC7D7E5F20D34432-001/init-core-data-001
[junit4] 2> 2399499 WARN (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=5 numCloses=5
[junit4] 2> 2399499 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true
[junit4] 2> 2399499 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason="", ssl=0.0/0.0, value=0.0/0.0, clientAuth=0.0/0.0)
[junit4] 2> 2399499 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 ####initCore
[junit4] 2> 2399500 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1/lib, /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 2399512 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0
[junit4] 2> 2399525 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.s.IndexSchema [null] Schema name=test
[junit4] 2> 2399586 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 2399691 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 2399691 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 2399698 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@449407be
[junit4] 2> 2399702 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@449407be
[junit4] 2> 2399702 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@449407be
[junit4] 2> 2399704 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1/lib, /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 2399718 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0
[junit4] 2> 2399730 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 2399790 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 2399794 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1, trusted=true
[junit4] 2> 2399794 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@449407be
[junit4] 2> 2399794 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 2399794 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.handler.RequestLoggingTest_DC7D7E5F20D34432-001/init-core-data-001/]
[junit4] 2> 2399795 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=44, maxMergeAtOnceExplicit=40, maxMergedSegmentMB=83.9736328125, floorSegmentMB=1.9921875, forceMergeDeletesPctAllowed=4.166643404818671, segmentsPerTier=18.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0, deletesPctAllowed=30.43498569054684
[junit4] 2> 2399826 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 2399826 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 2399826 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 2399826 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 2399827 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=24, maxMergeAtOnceExplicit=13, maxMergedSegmentMB=61.4560546875, floorSegmentMB=2.1103515625, forceMergeDeletesPctAllowed=18.37880392186092, segmentsPerTier=38.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0, deletesPctAllowed=31.42395329618669
[junit4] 2> 2399827 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@4eaa4df9[collection1] main]
[junit4] 2> 2399827 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 2400042 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 2400707 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 2400707 INFO (searcherExecutor-11477-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 2400707 INFO (coreLoadExecutor-11476-thread-1) [ x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1610590089719578624
[junit4] 2> 2400708 INFO (searcherExecutor-11477-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 2400708 INFO (searcherExecutor-11477-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 2400708 INFO (searcherExecutor-11477-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 2400708 INFO (searcherExecutor-11477-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 2400708 INFO (searcherExecutor-11477-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 2400708 INFO (searcherExecutor-11477-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 2400708 INFO (searcherExecutor-11477-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 2400708 INFO (searcherExecutor-11477-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 2400709 INFO (searcherExecutor-11477-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@4eaa4df9[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 2400709 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 ####initCore end
[junit4] 2> 2400713 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testLogBeforeExecuteWithRequestLogger
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.c.S.Request [collection1] webapp=null path=null params={q=*:*&wt=xml}
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.QueryComponent@6f6d8916
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.FacetComponent@6016b831
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.search.facet.FacetModule@39716577
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.MoreLikeThisComponent@34a68687
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.HighlightComponent@37008c3c
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.StatsComponent@62026ddd
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.ExpandComponent@50eaf637
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.TermsComponent@50f8d013
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding debug component:org.apache.solr.handler.component.DebugComponent@63aac75c
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.QueryComponent process: q=*:*&df=text&wt=xml&indent=off
[junit4] 2> 2400718 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.s.s.LocalStatsCache ## GET LocalSolrQueryRequest{q=*:*&df=text&wt=xml&indent=off}
[junit4] 2> 2400718 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.c.S.Request [collection1] webapp=null path=null params={q=*:*&wt=xml} hits=0 status=0 QTime=0
[junit4] 2> 2400719 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testLogBeforeExecuteWithRequestLogger
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RequestLoggingTest -Dtests.method=testLogBeforeExecuteWithRequestLogger -Dtests.seed=DC7D7E5F20D34432 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=uz-UZ -Dtests.timezone=America/Rosario -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[junit4] FAILURE 0.01s J0 | RequestLoggingTest.testLogBeforeExecuteWithRequestLogger <<<
[junit4] > Throwable #1: java.lang.AssertionError
[junit4] > at __randomizedtesting.SeedInfo.seed([DC7D7E5F20D34432:6D145E508D25FC7C]:0)
[junit4] > at org.apache.solr.handler.RequestLoggingTest.testLogBeforeExecute(RequestLoggingTest.java:88)
[junit4] > at org.apache.solr.handler.RequestLoggingTest.testLogBeforeExecuteWithRequestLogger(RequestLoggingTest.java:71)
[junit4] > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4] > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[junit4] > at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4] > at java.base/java.lang.reflect.Method.invoke(Method.java:564)
[junit4] > at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> 2400721 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testLogBeforeExecuteWithCoreLogger
[junit4] 2> 2400723 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.c.S.Request [collection1] webapp=null path=null params={q=*:*&wt=xml}
[junit4] 2> 2400723 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.QueryComponent process: q=*:*&df=text&wt=xml&indent=off
[junit4] 2> 2400723 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.s.s.LocalStatsCache ## GET LocalSolrQueryRequest{q=*:*&df=text&wt=xml&indent=off}
[junit4] 2> 2400723 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.c.S.Request [collection1] webapp=null path=null params={q=*:*&wt=xml} hits=0 status=0 QTime=0
[junit4] 2> 2400724 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testLogBeforeExecuteWithCoreLogger
[junit4] 2> 2400724 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> 2400724 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=440242743
[junit4] 2> 2400724 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 2400724 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@25629bad: rootName = null, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@6ab0f369
[junit4] 2> 2400727 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 2400727 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@43da4c0: rootName = null, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@2c39b529
[junit4] 2> 2400729 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 2400729 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@14299b78: rootName = null, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@4aec31ea
[junit4] 2> 2400729 INFO (coreCloseExecutor-11482-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@5c1b2a47
[junit4] 2> 2400729 INFO (coreCloseExecutor-11482-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=5c1b2a47
[junit4] 2> 2400729 INFO (coreCloseExecutor-11482-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@72e62fa2: rootName = null, domain = solr.core.collection1, service url = null, agent id = null] for registry solr.core.collection1 / com.codahale.metrics.MetricRegistry@18c09e45
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.handler.RequestLoggingTest_DC7D7E5F20D34432-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene80): {}, docValues:{}, maxPointsInLeafNode=1552, maxMBSortInHeap=6.688305152094994, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@2f35e635), locale=uz-UZ, timezone=America/Rosario
[junit4] 2> NOTE: Linux 4.15.0-32-generic amd64/Oracle Corporation 9.0.4 (64-bit)/cpus=8,threads=1,free=189884808,total=516423680
[junit4] 2> NOTE: All tests run in this JVM: [TestStressInPlaceUpdates, TestSortByMinMaxFunction, LeaderVoteWaitTimeoutTest, TolerantUpdateProcessorTest, MetricTriggerIntegrationTest, DocValuesMultiTest, TestCorePropertiesReload, SolrIndexMetricsTest, TestSmileRequest, CursorPagingTest, TestNonDefinedSimilarityFactory, TestBinaryField, ResponseBuilderTest, LeaderElectionContextKeyTest, SolrCoreMetricManagerTest, ClassificationUpdateProcessorFactoryTest, TestPullReplica, TriLevelCompositeIdRoutingTest, CustomHighlightComponentTest, AnalyticsMergeStrategyTest, PreAnalyzedFieldManagedSchemaCloudTest, RuleEngineTest, TestStressLucene, TestSolrCoreParser, TestClassicSimilarityFactory, TestCloudSchemaless, TestPayloadCheckQParserPlugin, DocumentAnalysisRequestHandlerTest, TestExclusionRuleCollectionAccess, ConfigureRecoveryStrategyTest, TestConfigSetsAPIZkFailure, TestRuleBasedAuthorizationPlugin, BaseCdcrDistributedZkTest, TestCoreAdminApis, CursorMarkTest, OverseerRolesTest, SimpleCollectionCreateDeleteTest, TestDistributedMissingSort, PeerSyncWithIndexFingerprintCachingTest, TestShardHandlerFactory, TestSolrCoreProperties, TestRandomDVFaceting, TestWithCollection, TestRandomRequestDistribution, HdfsAutoAddReplicasIntegrationTest, CloneFieldUpdateProcessorFactoryTest, TestCustomSort, QueryEqualityTest, ZkCLITest, TestCSVLoader, ReturnFieldsTest, ChaosMonkeyNothingIsSafeTest, TestWriterPerf, OverriddenZkACLAndCredentialsProvidersTest, CustomCollectionTest, TestScoreJoinQPNoScore, TestQueryTypes, TestSimNodeLostTrigger, DistributedFacetPivotWhiteBoxTest, IndexBasedSpellCheckerTest, DistributedExpandComponentTest, CreateCollectionCleanupTest, TestLeaderElectionZkExpiry, TestFieldCacheReopen, MultiThreadedOCPTest, MigrateRouteKeyTest, DeleteLastCustomShardedReplicaTest, DistribDocExpirationUpdateProcessorTest, TestDocBasedVersionConstraints, TestMiniSolrCloudClusterSSL, TestSolrXml, SuggestComponentTest, PluginInfoTest, CollectionsAPIAsyncDistributedZkTest, TestGraphTermsQParserPlugin, IgnoreLargeDocumentProcessorFactoryTest, PropertiesRequestHandlerTest, TestSearchPerf, TestCloudConsistency, TestHdfsCloudBackupRestore, DocExpirationUpdateProcessorFactoryTest, TestDistribIDF, TestRequestStatusCollectionAPI, TestIBSimilarityFactory, TestSolrQueryParser, TestDynamicLoading, TestSchemaNameResource, TestLogWatcher, TestRTimerTree, TestRecoveryHdfs, TestPushWriter, ChaosMonkeySafeLeaderWithPullReplicasTest, RandomizedTaggerTest, DistributedQueryComponentOptimizationTest, HdfsRecoveryZkTest, BufferStoreTest, SpellCheckComponentTest, TestGraphMLResponseWriter, TestLuceneMatchVersion, MaxSizeAutoCommitTest, GraphQueryTest, TestFreeTextSuggestions, InfixSuggestersTest, TestSolrCoreSnapshots, TriggerSetPropertiesIntegrationTest, BadCopyFieldTest, DataDrivenBlockJoinTest, ScheduledTriggerIntegrationTest, TestJsonFacetsStatsParsing, FileUtilsTest, BlobRepositoryCloudTest, NumericFieldsTest, ConjunctionSolrSpellCheckerTest, TokenizerChainTest, SolrCloudReportersTest, SliceStateTest, RequiredFieldsTest, TestManagedSchemaThreadSafety, WordBreakSolrSpellCheckerTest, CdcrVersionReplicationTest, HdfsThreadLeakTest, TestCloudPseudoReturnFields, MoreLikeThisHandlerTest, DistributedSuggestComponentTest, NodeAddedTriggerTest, ShardRoutingCustomTest, TestSimGenericDistributedQueue, ZkNodePropsTest, TestCrossCoreJoin, TestRestManager, RegexBoostProcessorTest, AddBlockUpdateTest, TestHalfAndHalfDocValues, ChangedSchemaMergeTest, AnalysisAfterCoreReloadTest, BasicFunctionalityTest, ConvertedLegacyTest, DisMaxRequestHandlerTest, DistributedIntervalFacetingTest, EchoParamsTest, SampleTest, TestDistributedSearch, TestDocumentBuilder, TestGroupingSearch, TestHighlightDedupGrouping, TestJoin, TestRandomFaceting, TestSimpleTrackingShardHandler, TestTolerantSearch, TestTrie, PathHierarchyTokenizerFactoryTest, ProtectedTermFilterFactoryTest, TestCharFilters, TestLuceneIndexBackCompat, TestEmbeddedSolrServerAdminHandler, TestEmbeddedSolrServerConstructors, ConnectionReuseTest, ActionThrottleTest, AliasIntegrationTest, CleanupOldIndexTest, ConcurrentCreateRoutedAliasTest, DeleteShardTest, DeleteStatusTest, DistributedVersionInfoTest, LeaderFailoverAfterPartitionTest, LeaderFailureAfterFreshStartTest, LegacyCloudClusterPropTest, MetricsHistoryIntegrationTest, MoveReplicaTest, MultiSolrCloudTestCaseTest, NodeMutatorTest, OutOfBoxZkACLAndCredentialsProvidersTest, OverseerTest, RollingRestartTest, SharedFSAutoReplicaFailoverTest, SolrXmlInZkTest, SyncSliceTest, TestCloudSearcherWarming, TestHashPartitioner, TestOnReconnectListenerSupport, TestSSLRandomization, TestSizeLimitedDistributedMap, TestSkipOverseerOperations, TestSolrCloudWithDelegationTokens, TestSolrCloudWithKerberosAlt, TestSolrCloudWithSecureImpersonation, TestStressCloudBlindAtomicUpdates, TestStressLiveNodes, TestTlogReplica, ZkFailoverTest, ConcurrentDeleteAndCreateCollectionTest, HdfsCollectionsAPIDistributedZkTest, ShardSplitTest, HDFSCollectionsAPITest, HdfsBasicDistributedZk2Test, HdfsBasicDistributedZkTest, HdfsChaosMonkeyNothingIsSafeTest, HdfsChaosMonkeySafeLeaderTest, HdfsNNFailoverTest, HdfsRecoverLeaseTest, HdfsWriteToMultipleCollectionsTest, ZkStateReaderTest, CachingDirectoryFactoryTest, ExitableDirectoryReaderTest, HdfsDirectoryFactoryTest, OpenCloseCoreStressTest, RequestHandlersTest, SolrCoreCheckLockOnStartupTest, SolrCoreTest, TestBackupRepositoryFactory, TestBadConfig, TestConfigOverlay, TestConfigSets, TestCustomStream, TestDirectoryFactory, TestDynamicURP, TestImplicitCoreProperties, TestInfoStreamLogging, TestLazyCores, TestMergePolicyConfig, TestNRTOpen, TestQuerySenderListener, TestQuerySenderNoQuery, TestReloadAndDeleteDocs, TestSolrDeletionPolicy1, PingRequestHandlerTest, RequestLoggingTest]
[junit4] Completed [574/832 (1!)] on J0 in 1.25s, 2 tests, 1 failure <<< FAILURES!
[...truncated 43045 lines...]
[repro] Jenkins log URL: https://jenkins.thetaphi.de/job/Lucene-Solr-master-Linux/22794/consoleText
[repro] Revision: a1ec716e107807f1dc24923cc7a91d0c5e64a7e1
[repro] Ant options: "-Dargs=-XX:+UseCompressedOops -XX:+UseParallelGC"
[repro] Repro line: ant test -Dtestcase=RequestLoggingTest -Dtests.method=testLogBeforeExecuteWithRequestLogger -Dtests.seed=DC7D7E5F20D34432 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=uz-UZ -Dtests.timezone=America/Rosario -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[repro] ant clean
[...truncated 6 lines...]
[repro] Test suites by module:
[repro] solr/core
[repro] RequestLoggingTest
[repro] ant compile-test
[...truncated 3423 lines...]
[repro] ant test-nocompile -Dtests.dups=5 -Dtests.maxfailures=5 -Dtests.class="*.RequestLoggingTest" -Dtests.showOutput=onerror "-Dargs=-XX:+UseCompressedOops -XX:+UseParallelGC" -Dtests.seed=DC7D7E5F20D34432 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=uz-UZ -Dtests.timezone=America/Rosario -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[...truncated 53 lines...]
[junit4] Suite: org.apache.solr.handler.RequestLoggingTest
[junit4] 2> 6702 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J2/temp/solr.handler.RequestLoggingTest_DC7D7E5F20D34432-001/init-core-data-001
[junit4] 2> 6712 WARN (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=1 numCloses=1
[junit4] 2> 6712 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=true
[junit4] 2> 6713 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason="", ssl=0.0/0.0, value=0.0/0.0, clientAuth=0.0/0.0)
[junit4] 2> 6714 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 ####initCore
[junit4] 2> 6715 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1/lib, /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 6741 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0
[junit4] 2> 6767 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.s.IndexSchema [null] Schema name=test
[junit4] 2> 6909 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 7074 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 7074 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.h.a.MetricsHistoryHandler No .system collection, keeping metrics history in memory.
[junit4] 2> 7094 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1605b6c4
[junit4] 2> 7095 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1605b6c4
[junit4] 2> 7095 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1605b6c4
[junit4] 2> 7113 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.c.SolrResourceLoader [null] Added 2 libs to classloader, from paths: [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1/lib, /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1/lib/classes]
[junit4] 2> 7152 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0
[junit4] 2> 7200 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.s.IndexSchema [collection1] Schema name=test
[junit4] 2> 7351 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 7382 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.c.CoreContainer Creating SolrCore 'collection1' using configuration from instancedir /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1, trusted=true
[junit4] 2> 7390 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr.core.collection1' (registry 'solr.core.collection1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1605b6c4
[junit4] 2> 7390 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 7390 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.c.SolrCore [[collection1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/core/src/test-files/solr/collection1], dataDir=[/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J2/temp/solr.handler.RequestLoggingTest_DC7D7E5F20D34432-001/init-core-data-001/]
[junit4] 2> 7393 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=44, maxMergeAtOnceExplicit=40, maxMergedSegmentMB=83.9736328125, floorSegmentMB=1.9921875, forceMergeDeletesPctAllowed=4.166643404818671, segmentsPerTier=18.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0, deletesPctAllowed=30.43498569054684
[junit4] 2> 7523 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 7523 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 7525 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 7525 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 7527 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=24, maxMergeAtOnceExplicit=13, maxMergedSegmentMB=61.4560546875, floorSegmentMB=2.1103515625, forceMergeDeletesPctAllowed=18.37880392186092, segmentsPerTier=38.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.0, deletesPctAllowed=31.42395329618669
[junit4] 2> 7528 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.s.SolrIndexSearcher Opening [Searcher@732719e3[collection1] main]
[junit4] 2> 7529 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 7553 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 7700 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 7700 INFO (searcherExecutor-26-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 7700 INFO (coreLoadExecutor-25-thread-1) [ x:collection1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1610591769033965568
[junit4] 2> 7702 INFO (searcherExecutor-26-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 7702 INFO (searcherExecutor-26-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 7702 INFO (searcherExecutor-26-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 7703 INFO (searcherExecutor-26-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 7704 INFO (searcherExecutor-26-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 7704 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 ####initCore end
[junit4] 2> 7705 INFO (searcherExecutor-26-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 7705 INFO (searcherExecutor-26-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 7708 INFO (searcherExecutor-26-thread-1-processing-x:collection1) [ x:collection1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 7708 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testLogBeforeExecuteWithRequestLogger
[junit4] 2> 7710 INFO (searcherExecutor-26-thread-1-processing-x:collection1) [ x:collection1] o.a.s.c.SolrCore [collection1] Registered new searcher Searcher@732719e3[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 7710 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.c.S.Request [collection1] webapp=null path=null params={q=*:*&wt=xml}
[junit4] 2> 7710 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.QueryComponent@592298ec
[junit4] 2> 7710 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.FacetComponent@332348e
[junit4] 2> 7710 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.search.facet.FacetModule@6154ed41
[junit4] 2> 7711 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.MoreLikeThisComponent@440a99c0
[junit4] 2> 7711 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.HighlightComponent@9a28c55
[junit4] 2> 7711 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.StatsComponent@1ba65fab
[junit4] 2> 7711 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.ExpandComponent@5d5e977b
[junit4] 2> 7711 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding component:org.apache.solr.handler.component.TermsComponent@4d8ac189
[junit4] 2> 7711 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.SearchHandler Adding debug component:org.apache.solr.handler.component.DebugComponent@50572c49
[junit4] 2> 7711 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.QueryComponent process: q=*:*&df=text&wt=xml&indent=off
[junit4] OK 0.01s J2 | RequestLoggingTest.testLogBeforeExecuteWithRequestLogger
[junit4] 2> 7711 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.s.s.LocalStatsCache ## GET LocalSolrQueryRequest{q=*:*&df=text&wt=xml&indent=off}
[junit4] 2> 7711 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.c.S.Request [collection1] webapp=null path=null params={q=*:*&wt=xml} hits=0 status=0 QTime=0
[junit4] 2> 7712 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithRequestLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testLogBeforeExecuteWithRequestLogger
[junit4] 2> 7717 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testLogBeforeExecuteWithCoreLogger
[junit4] 2> 7719 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.c.S.Request [collection1] webapp=null path=null params={q=*:*&wt=xml}
[junit4] 2> 7720 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.h.c.QueryComponent process: q=*:*&df=text&wt=xml&indent=off
[junit4] 2> 7720 DEBUG (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.s.s.LocalStatsCache ## GET LocalSolrQueryRequest{q=*:*&df=text&wt=xml&indent=off}
[junit4] 2> 7720 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.c.S.Request [collection1] webapp=null path=null params={q=*:*&wt=xml} hits=0 status=0 QTime=0
[junit4] 2> 7721 INFO (TEST-RequestLoggingTest.testLogBeforeExecuteWithCoreLogger-seed#[DC7D7E5F20D34432]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testLogBeforeExecuteWithCoreLogger
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RequestLoggingTest -Dtests.method=testLogBeforeExecuteWithCoreLogger -Dtests.seed=DC7D7E5F20D34432 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.badapples=true -Dtests.locale=uz-UZ -Dtests.timezone=America/Rosario -Dtests.asserts=true -Dtests.file.encoding=ISO-8859-1
[junit4] FAILURE 0.02s J2 | RequestLoggingTest.testLogBeforeExecuteWithCoreLogger <<<
[junit4] > Throwable #1: java.lang.AssertionError
[junit4] > at __randomizedtesting.SeedInfo.seed([DC7D7E5F20D34432:10FB7ED1DE1A2FA4]:0)
[junit4] > at org.apache.solr.handler.RequestLoggingTest.testLogBeforeExecute(RequestLoggingTest.java:88)
[junit4] > at org.apache.solr.handler.RequestLoggingTest.testLogBeforeExecuteWithCoreLogger(RequestLoggingTest.java:65)
[junit4] > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[junit4] > at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
[junit4] > at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[junit4] > at java.base/java.lang.reflect.Method.invoke(Method.java:564)
[junit4] > at java.base/java.lang.Thread.run(Thread.java:844)
[junit4] 2> 7733 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.SolrTestCaseJ4 ###deleteCore
[junit4] 2> 7733 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=1164503093
[junit4] 2> 7734 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 7734 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@520af6e7: rootName = null, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@48693666
[junit4] 2> 7740 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 7740 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@638d5e2b: rootName = null, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@2c178b5b
[junit4] 2> 7740 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 7740 INFO (SUITE-RequestLoggingTest-seed#[DC7D7E5F20D34432]-worker) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@5e6c76c2: rootName = null, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@42f8a6a9
[junit4] 2> 7744 INFO (coreCloseExecutor-31-thread-1) [ x:collection1] o.a.s.c.SolrCore [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@d7bf3b4
[junit4] 2> 7744 INFO (coreCloseExecutor-31-thread-1) [ x:collection1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.collection1, tag=d7bf3b4
[junit4] 2> 7745 INFO (coreCloseExecutor-31-thread-1) [ x:collection1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@bc9a52a: rootName = null, domain = solr.core.collection1, service url = null, agent id = null] for registry solr.core.collection1 / com.codahale.metrics.MetricRegistry@39937fda
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J2/temp/solr.handler.RequestLoggingTest_DC7D7E5F20D34432-001
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene80): {}, docValues:{}, maxPointsInLeafNode=1552, maxMBSortInHeap=6.688305152094994, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@65718a9c), locale=uz-UZ, timezone=America/Rosario
[junit4] 2> NOTE: Linux 4.15.0-32-generic amd64/Oracle Corporation 9.0.4 (64-bit)/cpus=8,threads=1,free=373595400,total=509083648
[junit4] 2> NOTE: All tests run in this JVM: [RequestLoggingTest, RequestLoggingTest]
[junit4] Completed [5/5 (1!)] on J2 in 1.13s, 2 tests, 1 failure <<< FAILURES!
[...truncated 11 lines...]
BUILD FAILED
/home/jenkins/workspace/Lucene-Solr-master-Linux/lucene/common-build.xml:1568: The following error occurred while executing this line:
/home/jenkins/workspace/Lucene-Solr-master-Linux/lucene/common-build.xml:1092: There were test failures: 5 suites, 10 tests, 1 failure [seed: DC7D7E5F20D34432]
Total time: 9 seconds
[repro] Setting last failure code to 256
[repro] Failures:
[repro] 1/5 failed: org.apache.solr.handler.RequestLoggingTest
[repro] Exiting with code 256
+ mv lucene/build lucene/build.repro
+ mv solr/build solr/build.repro
+ mv lucene/build.orig lucene/build
+ mv solr/build.orig solr/build
Archiving artifacts
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
[WARNINGS] Parsing warnings in console log with parser Java Compiler (javac)
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
<Git Blamer> Using GitBlamer to create author and commit information for all warnings.
<Git Blamer> GIT_COMMIT=a1ec716e107807f1dc24923cc7a91d0c5e64a7e1, workspace=/var/lib/jenkins/workspace/Lucene-Solr-master-Linux
[WARNINGS] Computing warning deltas based on reference build #22793
Recording test results
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
Build step 'Publish JUnit test result report' changed build result to UNSTABLE
Email was triggered for: Unstable (Test Failures)
Sending email for trigger: Unstable (Test Failures)
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2
Setting ANT_1_8_2_HOME=/var/lib/jenkins/tools/hudson.tasks.Ant_AntInstallation/ANT_1.8.2