IIS tests that look at EventLog are flaky

[BrennanConroy]

I've been looking at a few recent IIS test failures and they all have the same type of issue.

The error states "No entries matched by 'blah'" but if you look at the logs there is a log for the term being search for.

Example:

[43.463s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Stopping site, state: Stopped
[43.466s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Stopping pool, state: Stopping
[46.841s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Site has stopped successfully.
[47.940s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Host process shutting down.
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:38.191Z, PID: 5404] [aspnetcorev2.dll] Initializing logs for 'C:\h\w\B8B609FA\w\97FC08A1\e\ANCM\x64\aspnetcorev2.dll'. Process Id: 5404. File Version: 17.0.22100.0. Description: IIS ASP.NET Core Module V2. Commit: e9b2adb2a21cc2b0ae5b8f7e93aa4599d6f847b0.
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:38.586Z, PID: 5404] [aspnetcorev2.dll] Resolving hostfxr parameters for application: 'dotnet.exe' arguments: '' path: 'C:\h\w\B8B609FA\t\da1ee615614142aeadd80e12705ddb7c\'
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:38.831Z, PID: 5404] [aspnetcorev2.dll] Known dotnet.exe location: ''
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:40.497Z, PID: 5404] [aspnetcorev2.dll] Process path 'dotnet.exe' is dotnet, treating application as portable
Log being look for --> [47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:41.794Z, PID: 5404] [aspnetcorev2.dll] Event Log: 'Application 'C:\h\w\B8B609FA\t\da1ee615614142aeadd80e12705ddb7c\' failed to start. Exception message:
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Application arguments are empty.' 
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] End Event Log Message.
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:42.313Z, PID: 5404] [aspnetcorev2.dll] InvalidOperationException 'Application arguments are empty.' caught at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\CommonLib\HostFxrResolutionResult.cpp:64 
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:42.381Z, PID: 5404] [aspnetcorev2.dll] Failed HRESULT returned: 0x8007023e at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\AspNetCore\HandlerResolver.cpp:70 
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:42.474Z, PID: 5404] [aspnetcorev2.dll] Failed HRESULT returned: 0x8007023e at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\AspNetCore\HandlerResolver.cpp:175 
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:42.715Z, PID: 5404] [aspnetcorev2.dll] Failed HRESULT returned: 0x8007023e at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\AspNetCore\applicationinfo.cpp:195 
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:42.863Z, PID: 5404] [aspnetcorev2.dll] Failed HRESULT returned: 0x8007023e at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\AspNetCore\applicationinfo.cpp:108 
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:43.036Z, PID: 5404] [aspnetcorev2.dll] Event Log: 'Failed to start application '/LM/W3SVC/1/ROOT', ErrorCode '0x8007023e'.' 
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] End Event Log Message.
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:43.367Z, PID: 5404] [aspnetcorev2.dll] ASPNET_CORE_GLOBAL_MODULE::OnGlobalStopListening
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:43.845Z, PID: 5404] [aspnetcorev2.dll] Stopping application '/LM/W3SVC/1/ROOT'
[47.941s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2022-04-10T01:10:45.088Z, PID: 5404] [aspnetcorev2.dll] ASPNET_CORE_GLOBAL_MODULE::Terminate
[48.499s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [Time]: Total time taken for this test variation '48.4962277' seconds
[48.749s] [Microsoft.AspNetCore.Server.IIS.NewShim.FunctionalTests.StartupTests] [Error] Test threw an exception.
Xunit.Sdk.TrueException: No entries matched by 'Application 'C:\\h\\w\\B8B609FA\\t\\da1ee615614142aeadd80e12705ddb7c\\' failed to start. Exception message:\r\nApplication arguments are empty.'
Expected: True
Actual:   False
   at Xunit.Assert.True(Nullable`1 condition, String userMessage) in C:\Dev\xunit\xunit\src\xunit.assert\Asserts\BooleanAsserts.cs:line 95
   at Microsoft.AspNetCore.Server.IIS.FunctionalTests.EventLogHelpers.AssertEntry(String regexString, IEnumerable`1 entries, Boolean allowMultiple) in /_/src/Servers/IIS/IIS/test/Common.FunctionalTests/Infrastructure/EventLogHelpers.cs:line 72
   at Microsoft.AspNetCore.Server.IIS.FunctionalTests.EventLogHelpers.VerifyEventLogEvent(IISDeploymentResult deploymentResult, String expectedRegexMatchString, ILogger logger, Boolean allowMultiple) in /_/src/Servers/IIS/IIS/test/Common.FunctionalTests/Infrastructure/EventLogHelpers.cs:line 25
   at Microsoft.AspNetCore.Server.IIS.NewShim.FunctionalTests.StartupTests.InvalidProcessPath_ExpectServerError(String path, String arguments, String subError) in /_/src/Servers/IIS/IIS/test/Common.LongTests/StartupTests.cs:line 74
   at Xunit.Sdk.TestInvoker`1.<>c__DisplayClass48_1.<<InvokeTestMethodAsync>b__1>d.MoveNext() in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\Runners\TestInvoker.cs:line 273
--- End of stack trace from previous location ---
   at Xunit.Sdk.ExecutionTimer.AggregateAsync(Func`1 asyncAction) in C:\Dev\xunit\xunit\src\xunit.execution\Sdk\Frameworks\ExecutionTimer.cs:line 54
   at Xunit.Sdk.ExceptionAggregator.RunAsync(Func`1 code) in C:\Dev\xunit\xunit\src\xunit.core\Sdk\ExceptionAggregator.cs:line 96

And at the end of the logs there should be a list of every event log looked at:

aspnetcore/src/Servers/IIS/IIS/test/Common.FunctionalTests/Infrastructure/EventLogHelpers.cs

Lines 23 to 34 in 0f61a3d

	try
	{
	AssertEntry(expectedRegexMatchString, entries, allowMultiple);
	}
	catch (Exception)
	{
	foreach (var entry in entries)
	{
	logger.LogInformation("'{Message}', generated {Generated}, written {Written}", entry.Message, entry.TimeGenerated, entry.TimeWritten);
	}
	throw;
	}

But you can see that there are no additional logs at the end implying that no EventLogs were seen.

Here is a specific build link: https://dev.azure.com/dnceng/public/_build/results?buildId=1714229&view=ms.vss-test-web.build-test-results-tab&runId=46587798&paneView=debug&resultId=121955