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

@@ -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
 

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);

server/AyaNova/Startup.cs

@@ -102,9 +102,11 @@ namespace AyaNova
 #endif
 
             _log.LogDebug("BOOT: init EF service");
+
             services.AddEntityFrameworkNpgsql().AddDbContext<AyContext>(
-                options => options.UseNpgsql(_connectionString,
+                options => options.UseNpgsql(_connectionString
-                opt => opt.EnableRetryOnFailure())//http://www.npgsql.org/efcore/misc.html?q=execution%20strategy#execution-strategy
+                //,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,7 +403,7 @@ 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

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();
+                        //LOOKAT: 2018-10-10 15:34:34.0587|ERROR|Server Exception|Error=>System.InvalidOperationException: Sequence contains no elements
-                        MatchingKeywordIdList.Add(new MatchingDictionaryEntry() { DictionaryId = SearchDictionaryMatchFoundInDB.Id, InName = NameKeyWordList.Contains(KeyWord) });
+                        var SearchDictionaryMatchFoundInDB = ct.SearchDictionary.AsNoTracking().Where(x => x.Word == KeyWord).FirstOrDefault();
-                        //It exists now
+                        if (SearchDictionaryMatchFoundInDB != null)
-                        ExistingKeywordMatches.Add(SearchDictionaryMatchFoundInDB.Id, SearchDictionaryMatchFoundInDB.Word);
+                        {
+                            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){
+                    catch (Exception ex)
-                        var vv=ex.ToString();
+                    {
+                        log.LogInformation(ex, $"###################### Unexpected exception adding word: '{KeyWord}'!?");
+
                     }
                 }
             }
-
+            // transaction.Commit();
+            //}
             #endregion second attempt
 
             #region NEW WORD ADDITION: First naive attempt, clashing too much

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