[
https://issues.apache.org/jira/browse/SOLR-7603?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14565681#comment-14565681
]
Hoss Man commented on SOLR-7603:
--------------------------------
TL;DR: fairly certain this is a (nightly only) test bug caused by SOLR-7408,
working on fix
On IRC Tim drew my attention to some behavior of the LogUpdateProcessorFactory
that i had completely forgotten about...
{code}
@Override
public UpdateRequestProcessor getInstance(SolrQueryRequest req,
SolrQueryResponse rsp, UpdateRequestProcessor next) {
return LogUpdateProcessor.log.isInfoEnabled() ? new LogUpdateProcessor(req,
rsp, this, next) : null;
}
{code}
...in a nut shell: as an optimization, the factory doesn't produce a processor
if it can tell from the current logging level that there is no point in using
that processor.
Tim's theory was that some of the recent MDC/logging related changes may be
affecting hte log level used i nthe nightly tests -- but i'm fairly certain the
root cause is much more of a fluke...
SOLR-7408 introduced ConcurrentDeleteAndCreateCollectionTest in r1675274 on
"Apr 22 08:25:26 2015 UTC" .. this is an {{@Nightly}} test that has this bit of
code in it...
{code}
Logger.getLogger("org.apache.solr").setLevel(Level.WARN);
{code}
Which means if this test runs before UpdateRequestProcessorFactoryTest in the
same JVM, the log level won't be low enough for the LogUpdateProcessor to ever
be created.
I've confirmed that happeend in both of the very recent failures...
https://builds.apache.org/job/Lucene-Solr-NightlyTests-trunk/696/consoleText
{noformat}
[junit4] 2> NOTE: All tests run in this JVM: [NotRequiredUniqueKeyTest,
ShardSplitTest, DeleteLastCustomShardedReplicaTest, RequestLoggingTest,
TestReplicaProperties, TestCSVResponseWriter, TestShardHandlerFactory,
QueryEqualityTest, TestAnalyzeInfixSuggestions, TestSystemIdResolver,
InfoHandlerTest, TestLRUStatsCache, StatsComponentTest,
CoreAdminRequestStatusTest, SoftAutoCommitTest, FacetPivotSmallTest, TestTrie,
SimpleFacetsTest, TestExtendedDismaxParser, TestQueryUtils, TestDocSet,
TestPerFieldSimilarity, SolrCoreCheckLockOnStartupTest, SearchHandlerTest,
TestSchemaManager, DirectUpdateHandlerTest, HdfsChaosMonkeySafeLeaderTest,
SpellCheckCollatorTest, SolrInfoMBeanTest, TestConfigOverlay,
DistributedQueueTest, TestXIncludeConfig, TestSolrJ, OutputWriterTest,
HdfsLockFactoryTest, TestLeaderElectionZkExpiry, TestBM25SimilarityFactory,
AddSchemaFieldsUpdateProcessorFactoryTest, PathHierarchyTokenizerFactoryTest,
DistributedFacetPivotSmallAdvancedTest, BinaryUpdateRequestHandlerTest,
SOLR749Test, TestComplexPhraseQParserPlugin, TestRandomMergePolicy,
CachingDirectoryFactoryTest, LeaderElectionTest, HdfsNNFailoverTest,
TestManagedSchemaDynamicFieldResource, OverseerCollectionProcessorTest,
TestQuerySenderNoQuery, SortByFunctionTest, TestNRTOpen, AddBlockUpdateTest,
TestBinaryResponseWriter, AutoCommitTest, CloudExitableDirectoryReaderTest,
TestExactSharedStatsCache, HighlighterMaxOffsetTest,
TestDefaultSimilarityFactory, TestSchemaNameResource,
TestAuthorizationFramework, TestSchemaSimilarityResource,
TestCollationFieldDocValues, TestZkChroot,
ConcurrentDeleteAndCreateCollectionTest, BufferStoreTest, TestRestoreCore,
QueryResultKeyTest, TermVectorComponentDistributedTest,
TestFieldTypeCollectionResource, TestSolrConfigHandlerConcurrent,
MoreLikeThisHandlerTest, TestChildDocTransformer, CursorMarkTest,
TestSimpleQParserPlugin, XsltUpdateRequestHandlerTest, TestSurroundQueryParser,
OverseerTest, FullSolrCloudDistribCmdsTest, ZkSolrClientTest,
TestRandomDVFaceting, ZkCLITest, TestDistributedSearch,
TestDistributedGrouping, TestRecovery, TestRealTimeGet, TestStressReorder,
TestJoin, TestReload, HardAutoCommitTest, TestRangeQuery, TestGroupingSearch,
SolrCmdDistributorTest, PeerSyncTest, BadIndexSchemaTest, TestSort,
TestFiltering, BasicFunctionalityTest, TestIndexSearcher,
ShowFileRequestHandlerTest, CurrencyFieldOpenExchangeTest,
DistributedQueryElevationComponentTest, SolrIndexSplitterTest,
AnalysisAfterCoreReloadTest, SignatureUpdateProcessorFactoryTest,
SuggesterFSTTest, CoreAdminHandlerTest, SolrRequestParserTest,
TestFoldingMultitermQuery, DocValuesTest, SuggesterTest, SpatialFilterTest,
PolyFieldTest, NoCacheHeaderTest, WordBreakSolrSpellCheckerTest,
SchemaVersionSpecificBehaviorTest, TestPseudoReturnFields,
FieldMutatingUpdateProcessorTest, TestAtomicUpdateErrorCases,
DirectUpdateHandlerOptimizeTest, TestRemoteStreaming, TestSolrDeletionPolicy1,
StandardRequestHandlerTest, TestWriterPerf, DirectSolrSpellCheckerTest,
TestReversedWildcardFilterFactory, DocumentAnalysisRequestHandlerTest,
TestQueryTypes, PrimitiveFieldTypeTest, TestOmitPositions,
FileBasedSpellCheckerTest, XmlUpdateRequestHandlerTest, DocumentBuilderTest,
TestValueSourceCache, TestIndexingPerformance, RequiredFieldsTest,
FieldAnalysisRequestHandlerTest, TestSolrQueryParser, LoggingHandlerTest,
RegexBoostProcessorTest, SolrPluginUtilsTest, TestCollationField,
ReturnFieldsTest, UpdateRequestProcessorFactoryTest]
{noformat}
https://builds.apache.org/job/Lucene-Solr-NightlyTests-5.x/860/consoleText
{noformat}
[junit4] 2> NOTE: All tests run in this JVM: [TermVectorComponentTest,
MBeansHandlerTest, TestSolrDeletionPolicy1, TestDocumentBuilder,
HighlighterConfigTest, DistributedSpellCheckComponentTest, TestSchemaManager,
EnumFieldTest, TestNRTOpen, TestStressLucene, TestJoin,
AsyncMigrateRouteKeyTest, URLClassifyProcessorTest, TestBinaryField,
SignatureUpdateProcessorFactoryTest, TestJmxMonitoredMap,
TestIBSimilarityFactory, TestRandomFaceting, DistributedFacetPivotSmallTest,
TestEmbeddedSolrServerConstructors, AnalyticsMergeStrategyTest,
TestDFRSimilarityFactory, SuggesterWFSTTest, HdfsRecoveryZkTest,
TestReRankQParserPlugin, DistributedExpandComponentTest,
IndexBasedSpellCheckerTest, TestWordDelimiterFilterFactory, BufferStoreTest,
QueryElevationComponentTest, TestJettySolrRunner,
TestSweetSpotSimilarityFactory, DistribCursorPagingTest, TestArbitraryIndexDir,
DistributedFacetPivotLargeTest, TestConfig, TestBadConfig,
ConcurrentDeleteAndCreateCollectionTest, SolrCloudExampleTest,
TestUniqueKeyFieldResource, TestExceedMaxTermLength, BlockCacheTest,
SolrIndexConfigTest, CursorMarkTest, TestPhraseSuggestions,
TestImplicitCoreProperties, TestSolr4Spatial, TestRawResponseWriter,
TestFaceting, DateFieldTest, TestCryptoKeys, RuleEngineTest,
OverseerStatusTest, PrimitiveFieldTypeTest, ExternalFileFieldSortTest,
MultiThreadedOCPTest, RequestHandlersTest, TestRangeQuery, RulesTest,
ShardSplitTest, TestCodecSupport, RecoveryAfterSoftCommitTest,
CoreMergeIndexesAdminHandlerTest, LeaderElectionIntegrationTest,
SchemaVersionSpecificBehaviorTest, MinimalSchemaTest,
ParsingFieldUpdateProcessorsTest, ClusterStateTest, DateMathParserTest,
DebugComponentTest, TestLazyCores, TestManagedSchemaDynamicFieldResource,
ChaosMonkeyNothingIsSafeTest, SyncSliceTest, ZkNodePropsTest,
TestMergePolicyConfig, TestCSVLoader, SolrRequestParserTest, BasicZkTest,
TestFunctionQuery, ActionThrottleTest, BasicDistributedZkTest,
ChaosMonkeySafeLeaderTest, OverseerTest, ClusterStateUpdateTest, TestZkChroot,
TestRandomDVFaceting, ZkCLITest, TestDistributedSearch, ZkControllerTest,
TestRealTimeGet, DistributedTermsComponentTest, TestCoreContainer,
SolrCoreTest, PeerSyncTest, BadIndexSchemaTest, TestSort,
BasicFunctionalityTest, DirectUpdateHandlerTest, HighlighterTest,
SoftAutoCommitTest, ShowFileRequestHandlerTest, CurrencyFieldXmlFileTest,
SimplePostToolTest, TestExtendedDismaxParser, SuggesterFSTTest, DocValuesTest,
SuggesterTSTTest, PolyFieldTest, TestUpdate, TestAtomicUpdateErrorCases,
DirectUpdateHandlerOptimizeTest, DefaultValueUpdateProcessorTest,
SortByFunctionTest, TestRemoteStreaming, DocValuesMultiTest,
DistanceFunctionTest, SolrInfoMBeanTest, XsltUpdateRequestHandlerTest,
CacheHeaderTest, TestQueryUtils, StandardRequestHandlerTest, TestWriterPerf,
TestReversedWildcardFilterFactory, DocumentAnalysisRequestHandlerTest,
TestQueryTypes, TestOmitPositions, FileBasedSpellCheckerTest,
TermsComponentTest, DocumentBuilderTest, TestValueSourceCache,
PathHierarchyTokenizerFactoryTest, TestIndexingPerformance, RequiredFieldsTest,
FieldAnalysisRequestHandlerTest, TestSolrQueryParser,
FastVectorHighlighterTest, IndexSchemaRuntimeFieldTest, LoggingHandlerTest,
SolrPluginUtilsTest, IndexSchemaTest, TestJmxIntegration, TestCollationField,
UpdateRequestProcessorFactoryTest]
{noformat}
...ironically, one of the changes i recently made was to force the log level to
DEBUG for the duration of the UpdateRequestProcessorFactoryTest so we'd get
full logs in the even of failure -- so i'm pretty sure that will prevent the
failure from ever happening again. but what i plan to do as a more long term
fix:
* fix ConcurrentDeleteAndCreateCollectionTest to reset the log level it munges
* make UpdateRequestProcessorFactoryTest assert the neccessary log level needed
for LogUpdateProcessor to future proof us on similar bugs
* (eventually) remove the forced DEBUG that i just added to the test (once some
time has gone by w/o any other failures just in case i'm wrong)
> Scary non reproducible failure from
> UpdateRequestProcessorFactoryTest.testUpdateDistribChainSkipping
> ----------------------------------------------------------------------------------------------------
>
> Key: SOLR-7603
> URL: https://issues.apache.org/jira/browse/SOLR-7603
> Project: Solr
> Issue Type: Bug
> Reporter: Hoss Man
> Attachments: SOLR-7603.consoleText.txt
>
>
> jenkins nightly hit a very inexplicable error today...
> {noformat}
> Build: https://builds.apache.org/job/Lucene-Solr-NightlyTests-5.x/860/
> At revision 1682097
> Updating http://svn.apache.org/repos/asf/lucene/dev/branches/branch_5x at
> revision '2015-05-27T14:50:50.016 -0400'
> [java-info] java version "1.7.0_72"
> [java-info] Java(TM) SE Runtime Environment (1.7.0_72-b14, Oracle Corporation)
> [java-info] Java HotSpot(TM) 64-Bit Server VM (24.72-b04, Oracle Corporation)
> {noformat}
> {noformat}
> [junit4] 2> NOTE: reproduce with: ant test
> -Dtestcase=UpdateRequestProcessorFactoryTest
> -Dtests.method=testUpdateDistribChainSkipping -Dtests.seed=4ECABCCFD159BE21
> -Dtests.multiplier=2
> -Dtests.nightly=true -Dtests.slow=true
> -Dtests.linedocsfile=/x1/jenkins/lucene-data/enwiki.random.lines.txt
> -Dtests.locale=mt_MT -Dtests.timezone=Etc/GMT0 -Dtests.asserts=true
> -Dtests.file.encoding=ISO-8859-1
> [junit4] FAILURE 0.01s J0 |
> UpdateRequestProcessorFactoryTest.testUpdateDistribChainSkipping <<<
> [junit4] > Throwable #1: java.lang.AssertionError
> [junit4] > at
> __randomizedtesting.SeedInfo.seed([4ECABCCFD159BE21:3F2E4219A7B299ED]:0)
> [junit4] > at
> org.apache.solr.update.processor.UpdateRequestProcessorFactoryTest.testUpdateDistribChainSkipping(UpdateRequestProcessorFactoryTest.java:111)
> [junit4] > at java.lang.Thread.run(Thread.java:745)
> {noformat}
> ...the line in question is asserting that when executing a distributed update
> (ie: forwarded from another node), the LogUpdateProcessor is still part of
> the chain because it's got got the "RunAlways" annotation indicating it
> should always be included in the chain (everything before hte
> DistribUpdateProcessor is normally)
> There's really no explanation for why the LogUpdateProcessor wouldn't be
> found other then a code bug -- but in that case why doesn't the seed
> reproduce reliably?
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
