From 7e366f7718ec178388b120e02345c1210ee04f85 Mon Sep 17 00:00:00 2001 From: John Cardinal Date: Wed, 10 Oct 2018 23:25:13 +0000 Subject: [PATCH] commit prior to changing Search::processkeywords to use it's own db context as a test to get to the bottom of the weird concurrency issues --- devdocs/todo.txt | 4 ++++ server/AyaNova/Program.cs | 5 +++++ server/AyaNova/Startup.cs | 10 +++++---- server/AyaNova/biz/Search.cs | 33 +++++++++++++++++++++++------ test/raven-integration/burntest.bat | 6 ++---- 5 files changed, 43 insertions(+), 15 deletions(-) diff --git a/devdocs/todo.txt b/devdocs/todo.txt index 1634aba4..89d426f5 100644 --- a/devdocs/todo.txt +++ b/devdocs/todo.txt @@ -28,6 +28,10 @@ Once that is done then can steam ahead on the biz objects but until I have the c IMMEDIATE ITEMS: ================ + +- Re-test search with new processing code, do a huge test locally repeatedly for a bit + - If ok then move on to do the devops test again with a fresh build and huge db + - Put up copy to devops, build huge dataset, run all tests, pound it with 1000 runs, shake it out - Starting 1000 test runs at 2018-10-9-4:12pm diff --git a/server/AyaNova/Program.cs b/server/AyaNova/Program.cs index 7219126c..6a1a5965 100644 --- a/server/AyaNova/Program.cs +++ b/server/AyaNova/Program.cs @@ -101,6 +101,10 @@ namespace AyaNova var logRuleFilterOutMicrosoftEfCoreConcurrencyExceptions = new LoggingRule("Microsoft.EntityFrameworkCore.Update", NLog.LogLevel.Trace, NLog.LogLevel.Error, nullTarget); logRuleFilterOutMicrosoftEfCoreConcurrencyExceptions.Final = true; + var logRuleFilterOutMicrosoftEfCoreCommandExceptions = new LoggingRule("Microsoft.EntityFrameworkCore.Database.Command", NLog.LogLevel.Trace, NLog.LogLevel.Error, nullTarget); + logRuleFilterOutMicrosoftEfCoreCommandExceptions.Final = true; + + //Log all other regular items at selected level var logRuleAyaNovaItems = new LoggingRule("*", NLogLevel, fileTarget); @@ -116,6 +120,7 @@ namespace AyaNova //filter OUT microsoft stuff logConfig.LoggingRules.Add(logRuleFilterOutMicrosoft); logConfig.LoggingRules.Add(logRuleFilterOutMicrosoftEfCoreConcurrencyExceptions); + logConfig.LoggingRules.Add(logRuleFilterOutMicrosoftEfCoreCommandExceptions); } logConfig.LoggingRules.Add(logRuleAyaNovaItems); diff --git a/server/AyaNova/Startup.cs b/server/AyaNova/Startup.cs index 67e8b013..5e2b5adc 100644 --- a/server/AyaNova/Startup.cs +++ b/server/AyaNova/Startup.cs @@ -102,9 +102,11 @@ namespace AyaNova #endif _log.LogDebug("BOOT: init EF service"); + services.AddEntityFrameworkNpgsql().AddDbContext( - options => options.UseNpgsql(_connectionString, - opt => opt.EnableRetryOnFailure())//http://www.npgsql.org/efcore/misc.html?q=execution%20strategy#execution-strategy + options => options.UseNpgsql(_connectionString + //,opt => opt.EnableRetryOnFailure() + )//http://www.npgsql.org/efcore/misc.html?q=execution%20strategy#execution-strategy .ConfigureWarnings(warnings => //https://livebook.manning.com/#!/book/entity-framework-core-in-action/chapter-12/v-10/85 warnings.Throw( //Throw an exception on client eval, not necessarily an error but a smell Microsoft.EntityFrameworkCore.Diagnostics.RelationalEventId.QueryClientEvaluationWarning)) @@ -401,12 +403,12 @@ namespace AyaNova if (TESTING_REFRESH_DB) { AyaNova.Core.License.Fetch(apiServerState, dbContext, _log); - Util.Seeder.SeedDatabase(Util.Seeder.SeedLevel.HugeForLoadTest); + Util.Seeder.SeedDatabase(Util.Seeder.SeedLevel.SmallOneManShopTrialDataSet); } //TESTING #endif - + //Set autoId values ServerBootConfig.SetMostRecentAutoIdValuesFromDatabase(dbContext); diff --git a/server/AyaNova/biz/Search.cs b/server/AyaNova/biz/Search.cs index 1f18c58f..5a2d2405 100644 --- a/server/AyaNova/biz/Search.cs +++ b/server/AyaNova/biz/Search.cs @@ -19,6 +19,7 @@ namespace AyaNova.Biz //This class handles word breaking, processing keywords and searching for results public static class Search { + //private static ILogger log = AyaNova.Util.ApplicationLogging.CreateLogger("Search"); #region Search and return results @@ -443,6 +444,11 @@ namespace AyaNova.Biz //-------- START CRITICAL SECTION ----------- //------------------------------------------- #region NEW WORD ADDITION second attempt, do it word by word and accept clashes and handle them + + var log = AyaNova.Util.ApplicationLogging.CreateLogger("### Search::ProcessKeywords ###"); + + // using (var transaction = ct.Database.BeginTransaction()) + //{ foreach (string KeyWord in KeyWordList) { if (!ExistingKeywordMatches.ContainsValue(KeyWord)) @@ -464,24 +470,37 @@ namespace AyaNova.Biz } catch (Microsoft.EntityFrameworkCore.DbUpdateException ex) { + log.LogInformation($"###################### Exception caught attempting to add word: '{KeyWord}' fetching instead..."); //FAIL DUE TO OTHER CAUSE THAN WORD ALREADY ADDED? if (ex.InnerException == null || !ex.InnerException.Message.Contains("asearchdictionary_word_idx")) { + log.LogInformation($"###################### Unexpected inner exception on add word: '{KeyWord}'!?"); throw ex; } //FETCH THE WORD ID, PLACE IN MATCHINGKEYWORDLIST AND MOVE ON TO THE NEXT WORD - var SearchDictionaryMatchFoundInDB = ct.SearchDictionary.AsNoTracking().Where(x => x.Word == KeyWord).Single(); - MatchingKeywordIdList.Add(new MatchingDictionaryEntry() { DictionaryId = SearchDictionaryMatchFoundInDB.Id, InName = NameKeyWordList.Contains(KeyWord) }); - //It exists now - ExistingKeywordMatches.Add(SearchDictionaryMatchFoundInDB.Id, SearchDictionaryMatchFoundInDB.Word); + //LOOKAT: 2018-10-10 15:34:34.0587|ERROR|Server Exception|Error=>System.InvalidOperationException: Sequence contains no elements + var SearchDictionaryMatchFoundInDB = ct.SearchDictionary.AsNoTracking().Where(x => x.Word == KeyWord).FirstOrDefault(); + if (SearchDictionaryMatchFoundInDB != null) + { + MatchingKeywordIdList.Add(new MatchingDictionaryEntry() { DictionaryId = SearchDictionaryMatchFoundInDB.Id, InName = NameKeyWordList.Contains(KeyWord) }); + //It exists now + ExistingKeywordMatches.Add(SearchDictionaryMatchFoundInDB.Id, SearchDictionaryMatchFoundInDB.Word); + } + else + { + log.LogInformation($"###################### NULL when expected to find word: '{KeyWord}'!?"); + } } - catch(Exception ex){ - var vv=ex.ToString(); + catch (Exception ex) + { + log.LogInformation(ex, $"###################### Unexpected exception adding word: '{KeyWord}'!?"); + } } } - + // transaction.Commit(); + //} #endregion second attempt #region NEW WORD ADDITION: First naive attempt, clashing too much diff --git a/test/raven-integration/burntest.bat b/test/raven-integration/burntest.bat index 3f6efcc5..b2a426d8 100644 --- a/test/raven-integration/burntest.bat +++ b/test/raven-integration/burntest.bat @@ -2,10 +2,8 @@ SET /a VAR=0 :HOME SET /a VAR=VAR+1 rem 1000 runs in local debug mode server is about 6 hours at current test pace with huge data -IF %VAR%==1000 goto :End +IF %VAR%==100 goto :End dotnet test -goto :HOME - -:END \ No newline at end of file +goto :HOME \ No newline at end of file