Try to reduce IIS test event log flakiness (#57028)

dotnet · Jul 31, 2024 · f018f0b · f018f0b
1 parent 42e6172
commit f018f0b
Show file tree

Hide file tree

Showing 7 changed files with 71 additions and 57 deletions.
diff --git a/src/Servers/IIS/IIS/test/Common.FunctionalTests/Infrastructure/EventLogHelpers.cs b/src/Servers/IIS/IIS/test/Common.FunctionalTests/Infrastructure/EventLogHelpers.cs
@@ -15,17 +15,17 @@ namespace Microsoft.AspNetCore.Server.IIS.FunctionalTests;
 
 public class EventLogHelpers
 {
-    public static void VerifyEventLogEvent(IISDeploymentResult deploymentResult, string expectedRegexMatchString, ILogger logger, bool allowMultiple = false)
+    public static async Task VerifyEventLogEventAsync(IISDeploymentResult deploymentResult, string expectedRegexMatchString, ILogger logger, bool allowMultiple = false)
     {
         Assert.True(deploymentResult.HostProcess.HasExited);
 
-        var entries = GetEntries(deploymentResult);
         try
         {
-            AssertEntry(expectedRegexMatchString, entries, allowMultiple);
+            await AssertEntryAsync(expectedRegexMatchString, deploymentResult, allowMultiple);
         }
         catch (Exception)
         {
+            var entries = GetEntries(deploymentResult);
             foreach (var entry in entries)
             {
                 logger.LogInformation("'{Message}', generated {Generated}, written {Written}", entry.Message, entry.TimeGenerated, entry.TimeWritten);
@@ -34,22 +34,16 @@ public static void VerifyEventLogEvent(IISDeploymentResult deploymentResult, str
         }
     }
 
-    public static void VerifyEventLogEvents(IISDeploymentResult deploymentResult, params string[] expectedRegexMatchString)
+    public static async Task VerifyEventLogEvents(IISDeploymentResult deploymentResult, params string[] expectedRegexMatchString)
     {
         Assert.True(deploymentResult.HostProcess.HasExited);
 
         var entries = GetEntries(deploymentResult).ToList();
-        foreach (var regexString in expectedRegexMatchString)
+        for (var i = 0; i < expectedRegexMatchString.Length; i++)
         {
-            var matchedEntries = AssertEntry(regexString, entries);
-
-            foreach (var matchedEntry in matchedEntries)
-            {
-                entries.Remove(matchedEntry);
-            }
+            var matchedEntries = await AssertEntryAsync(expectedRegexMatchString[i], deploymentResult);
+            Assert.True(matchedEntries is not null, $"Regex {expectedRegexMatchString[i]} was not found.");
         }
-
-        Assert.True(0 == entries.Count, $"Some entries were not matched by any regex {FormatEntries(entries)}");
     }
 
     public static string OnlyOneAppPerAppPool()
@@ -65,13 +59,33 @@ public static string OnlyOneAppPerAppPool()
         }
     }
 
-    private static EventLogEntry[] AssertEntry(string regexString, IEnumerable<EventLogEntry> entries, bool allowMultiple = false)
+    private static async Task<EventLogEntry[]> AssertEntryAsync(string regexString, IISDeploymentResult deploymentResult, bool allowMultiple = false)
     {
+        EventLogEntry[] matchedEntries = [];
         var expectedRegex = new Regex(regexString, RegexOptions.Singleline);
-        var matchedEntries = entries.Where(entry => expectedRegex.IsMatch(entry.Message)).ToArray();
-        Assert.True(matchedEntries.Length > 0, $"No entries matched by '{regexString}'");
-        Assert.True(allowMultiple || matchedEntries.Length < 2, $"Multiple entries matched by '{regexString}': {FormatEntries(matchedEntries)}");
+
+        // EventLogs don't seem to be instant, add retries to attempt to reduce test failures when looking for logs.
+        for (var i = 10; i > 0; i--)
+        {
+            var entries = GetEntries(deploymentResult);
+            matchedEntries = entries.Where(entry => expectedRegex.IsMatch(entry.Message)).ToArray();
+            if (matchedEntries.Length == 0)
+            {
+                await Task.Delay(100);
+                continue;
+            }
+            AssertEntries();
+            return matchedEntries;
+        }
+
+        AssertEntries();
         return matchedEntries;
+
+        void AssertEntries()
+        {
+            Assert.True(matchedEntries.Length > 0, $"No entries matched by '{regexString}'");
+            Assert.True(allowMultiple || matchedEntries.Length < 2, $"Multiple entries matched by '{regexString}': {FormatEntries(matchedEntries)}");
+        }
     }
 
     private static string FormatEntries(IEnumerable<EventLogEntry> entries)

diff --git a/src/Servers/IIS/IIS/test/Common.FunctionalTests/LoggingTests.cs b/src/Servers/IIS/IIS/test/Common.FunctionalTests/LoggingTests.cs
@@ -100,7 +100,7 @@ public async Task InvalidFilePathForLogs_ServerStillRuns(TestVariant variant)
         if (variant.HostingModel == HostingModel.InProcess)
         {
             // Error is getting logged twice, from shim and handler
-            EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.CouldNotStartStdoutFileRedirection("Q:\\std", deploymentResult), Logger, allowMultiple: true);
+            await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.CouldNotStartStdoutFileRedirection("Q:\\std", deploymentResult), Logger, allowMultiple: true);
         }
     }
 
@@ -190,7 +190,7 @@ public async Task DebugLogsAreWrittenToEventLog(TestVariant variant)
         deploymentParameters.HandlerSettings["debugLevel"] = "file,eventlog";
         var deploymentResult = await StartAsync(deploymentParameters);
         StopServer();
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, @"\[aspnetcorev2.dll\] Initializing logs for .*?Description: IIS ASP.NET Core Module V2", Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, @"\[aspnetcorev2.dll\] Initializing logs for .*?Description: IIS ASP.NET Core Module V2", Logger);
     }
 
     [ConditionalTheory]
@@ -216,7 +216,7 @@ public async Task CheckUTF8File(TestVariant variant)
 
         var contents = Helpers.ReadAllTextFromFile(Helpers.GetExpectedLogName(deploymentResult, logFolderPath), Logger);
         Assert.Contains("彡⾔", contents);
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.InProcessThreadExitStdOut(deploymentResult, "12", "(.*)彡⾔(.*)"), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.InProcessThreadExitStdOut(deploymentResult, "12", "(.*)彡⾔(.*)"), Logger);
     }
 
     [ConditionalTheory]
@@ -246,7 +246,7 @@ public async Task CaptureLogsForOutOfProcessWhenProcessFailsToStart()
 
         StopServer();
 
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, "Wow!"), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, "Wow!"), Logger);
     }
 
     [ConditionalFact]
@@ -262,7 +262,7 @@ public async Task DisableRedirectionNoLogs()
 
         StopServer();
 
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, ""), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, ""), Logger);
     }
 
     [ConditionalFact]
@@ -276,7 +276,7 @@ public async Task CaptureLogsForOutOfProcessWhenProcessFailsToStart30KbMax()
 
         StopServer();
 
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, new string('a', 30000)), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, new string('a', 30000)), Logger);
     }
 
     [ConditionalTheory]

diff --git a/src/Servers/IIS/IIS/test/Common.FunctionalTests/MultiApplicationTests.cs b/src/Servers/IIS/IIS/test/Common.FunctionalTests/MultiApplicationTests.cs
@@ -67,7 +67,7 @@ public async Task FailsAndLogsWhenRunningTwoInProcessApps()
             Assert.Contains("500.35", await result2.Content.ReadAsStringAsync());
         }
 
-        EventLogHelpers.VerifyEventLogEvent(result, EventLogHelpers.OnlyOneAppPerAppPool(), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(result, EventLogHelpers.OnlyOneAppPerAppPool(), Logger);
     }
 
     [ConditionalTheory]
@@ -94,7 +94,7 @@ public async Task FailsAndLogsEventLogForMixedHostingModel(HostingModel firstApp
             Assert.Contains("500.34", await result2.Content.ReadAsStringAsync());
         }
 
-        EventLogHelpers.VerifyEventLogEvent(result, "Mixed hosting model is not supported.", Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(result, "Mixed hosting model is not supported.", Logger);
     }
 
     private void SetHostingModel(string directory, HostingModel model)

diff --git a/src/Servers/IIS/IIS/test/Common.LongTests/ShutdownTests.cs b/src/Servers/IIS/IIS/test/Common.LongTests/ShutdownTests.cs
@@ -49,7 +49,7 @@ public async Task ShutdownTimeoutIsApplied()
 
         StopServer();
 
-        EventLogHelpers.VerifyEventLogEvents(deploymentResult,
+        await EventLogHelpers.VerifyEventLogEvents(deploymentResult,
             EventLogHelpers.InProcessStarted(deploymentResult),
             EventLogHelpers.InProcessFailedToStop(deploymentResult, ""));
     }
@@ -256,7 +256,7 @@ await statusConnection.Receive("5",
         deploymentResult.AssertWorkerProcessStop();
 
         // Shutdown should be graceful here!
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult,
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult,
             EventLogHelpers.ShutdownMessage(deploymentResult), Logger);
     }
 
@@ -293,7 +293,7 @@ public async Task RequestsWhileRestartingAppFromConfigChangeAreProcessed()
         await deploymentResult.AssertRecycledAsync();
 
         // Shutdown should be graceful here!
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult,
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult,
             EventLogHelpers.ShutdownMessage(deploymentResult), Logger);
     }
 
@@ -330,7 +330,7 @@ public async Task RequestsWhileRecyclingAppAreProcessed()
         await deploymentResult.AssertRecycledAsync();
 
         // Shutdown should be graceful here!
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult,
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult,
             EventLogHelpers.ShutdownMessage(deploymentResult), Logger);
     }
 

diff --git a/src/Servers/IIS/IIS/test/Common.LongTests/StartupTests.cs b/src/Servers/IIS/IIS/test/Common.LongTests/StartupTests.cs
@@ -71,7 +71,7 @@ public async Task InvalidProcessPath_ExpectServerError(string path, string argum
 
         StopServer();
 
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.UnableToStart(deploymentResult, subError), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.UnableToStart(deploymentResult, subError), Logger);
         if (DeployerSelector.HasNewShim)
         {
             Assert.Contains("500.0", await response.Content.ReadAsStringAsync());
@@ -180,7 +180,7 @@ public async Task DoesNotStartIfDisabled()
 
             StopServer();
 
-            EventLogHelpers.VerifyEventLogEvent(deploymentResult, "AspNetCore Module is disabled", Logger);
+            await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, "AspNetCore Module is disabled", Logger);
         }
     }
 
@@ -230,7 +230,7 @@ public async Task DetectsOverriddenServer()
 
         StopServer();
 
-        EventLogHelpers.VerifyEventLogEvents(deploymentResult,
+        await EventLogHelpers.VerifyEventLogEvents(deploymentResult,
             EventLogHelpers.InProcessFailedToStart(deploymentResult, "CLR worker thread exited prematurely"),
             EventLogHelpers.InProcessThreadException(deploymentResult, ".*?Application is running inside IIS process but is not configured to use IIS server"));
     }
@@ -248,7 +248,7 @@ public async Task LogsStartupExceptionExitError()
 
         StopServer();
 
-        EventLogHelpers.VerifyEventLogEvents(deploymentResult,
+        await EventLogHelpers.VerifyEventLogEvents(deploymentResult,
             EventLogHelpers.InProcessFailedToStart(deploymentResult, "CLR worker thread exited prematurely"),
             EventLogHelpers.InProcessThreadException(deploymentResult, ", exception code = '0xe0434352'"));
     }
@@ -265,7 +265,7 @@ public async Task LogsUnexpectedThreadExitError()
 
         StopServer();
 
-        EventLogHelpers.VerifyEventLogEvents(deploymentResult,
+        await EventLogHelpers.VerifyEventLogEvents(deploymentResult,
             EventLogHelpers.InProcessFailedToStart(deploymentResult, "CLR worker thread exited prematurely"),
             EventLogHelpers.InProcessThreadExit(deploymentResult, "12"));
     }
@@ -291,7 +291,7 @@ public async Task RemoveHostfxrFromApp_InProcessHostfxrAPIAbsent()
             await AssertSiteFailsToStartWithInProcessStaticContent(deploymentResult);
         }
 
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.InProcessHostfxrInvalid(deploymentResult), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.InProcessHostfxrInvalid(deploymentResult), Logger);
     }
 
     [ConditionalFact]
@@ -354,7 +354,7 @@ public async Task RemoveHostfxrFromApp_InProcessHostfxrLoadFailure()
             await AssertSiteFailsToStartWithInProcessStaticContent(deploymentResult);
         }
 
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.InProcessHostfxrUnableToLoad(deploymentResult), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.InProcessHostfxrUnableToLoad(deploymentResult), Logger);
     }
 
     [ConditionalFact]
@@ -373,7 +373,7 @@ public async Task TargetDifferenceSharedFramework_FailedToFindNativeDependencies
             await AssertSiteFailsToStartWithInProcessStaticContent(deploymentResult);
         }
 
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.InProcessFailedToFindNativeDependencies(deploymentResult), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.InProcessFailedToFindNativeDependencies(deploymentResult), Logger);
     }
 
     [ConditionalFact]
@@ -393,7 +393,7 @@ public async Task WrongApplicationPath_FailedToRun()
 
         await AssertSiteFailsToStartWithInProcessStaticContent(deploymentResult, "500.31", "Provided application path does not exist, or isn't a .dll or .exe.");
 
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.InProcessFailedToFindApplication(), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.InProcessFailedToFindApplication(), Logger);
     }
 
     [ConditionalFact]
@@ -450,13 +450,13 @@ public async Task RemoveInProcessReference_FailedToFindRequestHandler()
         {
             await AssertSiteFailsToStartWithInProcessStaticContent(deploymentResult, "500.33");
 
-            EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.InProcessFailedToFindRequestHandler(deploymentResult), Logger);
+            await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.InProcessFailedToFindRequestHandler(deploymentResult), Logger);
         }
         else
         {
             await AssertSiteFailsToStartWithInProcessStaticContent(deploymentResult);
 
-            EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.InProcessFailedToFindRequestHandler(deploymentResult), Logger);
+            await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.InProcessFailedToFindRequestHandler(deploymentResult), Logger);
         }
     }
 
@@ -482,7 +482,7 @@ public async Task StartupTimeoutIsApplied()
             // Startup timeout now recycles process.
             deploymentResult.AssertWorkerProcessStop();
 
-            EventLogHelpers.VerifyEventLogEvent(deploymentResult,
+            await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult,
                 EventLogHelpers.InProcessFailedToStart(deploymentResult, "Managed server didn't initialize after 1000 ms."),
                 Logger);
 
@@ -514,7 +514,7 @@ public async Task StartupTimeoutIsApplied_DisableRecycleOnStartupTimeout()
 
             StopServer(gracefulShutdown: false);
 
-            EventLogHelpers.VerifyEventLogEvent(deploymentResult,
+            await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult,
                 EventLogHelpers.InProcessFailedToStart(deploymentResult, "Managed server didn't initialize after 1000 ms."),
                 Logger);
 
@@ -540,7 +540,7 @@ public async Task CheckInvalidHostingModelParameter()
 
         StopServer();
 
-        EventLogHelpers.VerifyEventLogEvents(deploymentResult,
+        await EventLogHelpers.VerifyEventLogEvents(deploymentResult,
             EventLogHelpers.ConfigurationLoadError(deploymentResult, "Unknown hosting model 'bogus'. Please specify either hostingModel=\"inprocess\" or hostingModel=\"outofprocess\" in the web.config file.")
             );
     }
@@ -564,7 +564,7 @@ public async Task ReportsWebConfigAuthoringErrors(string scenario)
 
         StopServer();
 
-        EventLogHelpers.VerifyEventLogEvents(deploymentResult,
+        await EventLogHelpers.VerifyEventLogEvents(deploymentResult,
             EventLogHelpers.ConfigurationLoadError(deploymentResult, expectedError)
         );
     }
@@ -1006,7 +1006,7 @@ public async Task CheckStdoutWithLargeWrites_TestSink(string mode)
         Assert.Contains(TestSink.Writes, context => context.Message.Contains(expectedLogString));
         var expectedEventLogString = new string('a', 30000);
 
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.InProcessThreadExitStdOut(deploymentResult, "12", expectedEventLogString), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.InProcessThreadExitStdOut(deploymentResult, "12", expectedEventLogString), Logger);
     }
 
     [ConditionalTheory]
@@ -1032,7 +1032,7 @@ public async Task CheckStdoutWithLargeWrites_LogFile(string mode)
 
         var expectedEventLogString = new string('a', 30000);
 
-        EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.InProcessThreadExitStdOut(deploymentResult, "12", expectedEventLogString), Logger);
+        await EventLogHelpers.VerifyEventLogEventAsync(deploymentResult, EventLogHelpers.InProcessThreadExitStdOut(deploymentResult, "12", expectedEventLogString), Logger);
     }
 
     [ConditionalFact]

diff --git a/src/Servers/IIS/IIS/test/IIS.Shared.FunctionalTests/ApplicationInitializationTests.cs b/src/Servers/IIS/IIS/test/IIS.Shared.FunctionalTests/ApplicationInitializationTests.cs
@@ -57,11 +57,11 @@ public async Task ApplicationPreloadStartsApp(HostingModel hostingModel, bool de
 
             await Helpers.Retry(async () => await File.ReadAllTextAsync(Path.Combine(result.ContentRoot, "Started.txt")), TimeoutExtensions.DefaultTimeoutValue);
             StopServer();
-            EventLogHelpers.VerifyEventLogEvent(result, EventLogHelpers.Started(result), Logger);
+            await EventLogHelpers.VerifyEventLogEventAsync(result, EventLogHelpers.Started(result), Logger);
 
             if (delayShutdown)
             {
-                EventLogHelpers.VerifyEventLogEvent(result, EventLogHelpers.ShutdownMessage(result), Logger);
+                await EventLogHelpers.VerifyEventLogEventAsync(result, EventLogHelpers.ShutdownMessage(result), Logger);
             }
             else
             {
@@ -101,8 +101,8 @@ public async Task ApplicationInitializationPageIsRequested(HostingModel hostingM
 
             await Helpers.Retry(async () => await File.ReadAllTextAsync(Path.Combine(result.ContentRoot, "Started.txt")), TimeoutExtensions.DefaultTimeoutValue);
             StopServer();
-            EventLogHelpers.VerifyEventLogEvent(result, EventLogHelpers.Started(result), Logger);
-            EventLogHelpers.VerifyEventLogEvent(result, EventLogHelpers.ShutdownMessage(result), Logger);
+            await EventLogHelpers.VerifyEventLogEventAsync(result, EventLogHelpers.Started(result), Logger);
+            await EventLogHelpers.VerifyEventLogEventAsync(result, EventLogHelpers.ShutdownMessage(result), Logger);
         }
     }