Skip to content

Flaky test CheckStdoutWithLargeWrites_TestSink #52734

Open
@amcasey

Description

@amcasey

Failing Test(s)

  • Microsoft.AspNetCore.Server.IIS.IISExpress.FunctionalTests.StartupTests.CheckStdoutWithLargeWrites_TestSink(mode: "CheckOversizedStdOutWrites")

Error Message

No entries matched by 'Application '/LM/W3SVC/1/ROOT' with physical root 'C:\h\w\A924098E\t\7c445d1437fc4ea295628026e36946c4' has exited from Program.Main with exit code = '12'. First 30KB characters of captured stdout and stderr logs:
aaaa[SNIP]'
Expected: True
Actual:   False

Note: I dropped a lot of the aaaa sequence to satisfy GH's limits.

Stacktrace

   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.IISExpress.FunctionalTests.StartupTests.CheckStdoutWithLargeWrites_TestSink(String mode) in /_/src/Servers/IIS/IIS/test/Common.LongTests/StartupTests.cs:line 1007

Logs

[0.001s] [TestLifetime] [Information] Starting test CheckStdoutWithLargeWrites_LogFile-CheckOversizedStdOutWrites at 2023-12-11T14:43:01
[0.006s] [....IISExpressDeployer] [Information] Deploying [Variation] :: ServerType=IISExpress, Runtime=CoreClr, Arch=x64, BaseUrlHint=, Publish=True
[0.006s] [....IISExpressDeployer] [Information] Microsoft Windows NT 10.0.22000.0
[0.007s] [....IISExpressDeployer] [Information] Using prepublished application from C:\h\w\A924098E\w\BA950A05\e\InProcessWebSite-Portable
[0.010s] [....IISExpressDeployer] [Debug] Processing C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\ARM64
[0.010s] [....IISExpressDeployer] [Debug]   Copying aspnetcorev2_inprocess.dll
[0.012s] [....IISExpressDeployer] [Debug] Processing C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\runtimes\win\lib\net9.0
[0.012s] [....IISExpressDeployer] [Debug]   Copying System.Diagnostics.EventLog.dll
[0.012s] [....IISExpressDeployer] [Debug]   Copying System.Diagnostics.EventLog.Messages.dll
[0.013s] [....IISExpressDeployer] [Debug] Processing C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\runtimes\win\lib
[0.013s] [....IISExpressDeployer] [Debug] Processing C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\runtimes\win
[0.013s] [....IISExpressDeployer] [Debug] Processing C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\runtimes
[0.013s] [....IISExpressDeployer] [Debug] Processing C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\wwwroot
[0.013s] [....IISExpressDeployer] [Debug]   Copying static.txt
[0.014s] [....IISExpressDeployer] [Debug] Processing C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\x64
[0.014s] [....IISExpressDeployer] [Debug]   Copying aspnetcorev2_inprocess.dll
[0.015s] [....IISExpressDeployer] [Debug] Processing C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\x86
[0.015s] [....IISExpressDeployer] [Debug]   Copying aspnetcorev2_inprocess.dll
[0.015s] [....IISExpressDeployer] [Debug] Processing C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea
[0.016s] [....IISExpressDeployer] [Debug]   Copying InProcessWebSite.deps.json
[0.019s] [....IISExpressDeployer] [Debug]   Copying InProcessWebSite.dll
[0.019s] [....IISExpressDeployer] [Debug]   Copying InProcessWebSite.exe
[0.020s] [....IISExpressDeployer] [Debug]   Copying InProcessWebSite.pdb
[0.020s] [....IISExpressDeployer] [Debug]   Copying InProcessWebSite.runtimeconfig.json
[0.021s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Abstractions.dll
[0.021s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Abstractions.pdb
[0.022s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Abstractions.xml
[0.022s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Core.dll
[0.023s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Core.pdb
[0.023s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Core.xml
[0.024s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Connections.Abstractions.dll
[0.024s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Connections.Abstractions.pdb
[0.027s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Connections.Abstractions.xml
[0.028s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Abstractions.dll
[0.028s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Abstractions.pdb
[0.029s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Abstractions.xml
[0.029s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.dll
[0.030s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.pdb
[0.030s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Server.Abstractions.dll
[0.031s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Server.Abstractions.pdb
[0.031s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Server.Abstractions.xml
[0.036s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.xml
[0.037s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Abstractions.dll
[0.037s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Abstractions.pdb
[0.038s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Abstractions.xml
[0.038s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.dll
[0.039s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Extensions.dll
[0.039s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Extensions.pdb
[0.040s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Extensions.xml
[0.040s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Features.dll
[0.041s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Features.pdb
[0.041s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Features.xml
[0.042s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.pdb
[0.042s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.xml
[0.045s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpOverrides.dll
[0.046s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpOverrides.pdb
[0.049s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpOverrides.xml
[0.049s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpsPolicy.dll
[0.050s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpsPolicy.pdb
[0.050s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpsPolicy.xml
[0.051s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.ResponseCompression.dll
[0.051s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.ResponseCompression.pdb
[0.052s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.ResponseCompression.xml
[0.052s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.HttpSys.dll
[0.053s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.HttpSys.pdb
[0.053s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.HttpSys.xml
[0.057s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IIS.dll
[0.057s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IIS.pdb
[0.058s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IIS.xml
[0.058s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IISIntegration.dll
[0.059s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IISIntegration.pdb
[0.059s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IISIntegration.xml
[0.060s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Core.dll
[0.060s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Core.pdb
[0.061s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Core.xml
[0.061s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.dll
[0.062s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.pdb
[0.062s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.dll
[0.066s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.pdb
[0.066s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.NamedPipes.xml
[0.067s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.dll
[0.067s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.pdb
[0.068s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.xml
[0.092s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.dll
[0.093s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.pdb
[0.093s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.xml
[0.094s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.xml
[0.094s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.WebUtilities.dll
[0.095s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.WebUtilities.pdb
[0.095s] [....IISExpressDeployer] [Debug]   Copying Microsoft.AspNetCore.WebUtilities.xml
[0.096s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.Abstractions.dll
[0.096s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.Binder.dll
[0.097s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.CommandLine.dll
[0.097s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.dll
[0.098s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.EnvironmentVariables.dll
[0.098s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.FileExtensions.dll
[0.099s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.Json.dll
[0.099s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.UserSecrets.dll
[0.100s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.DependencyInjection.Abstractions.dll
[0.100s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.DependencyInjection.dll
[0.104s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Diagnostics.Abstractions.dll
[0.104s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Diagnostics.dll
[0.105s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Features.dll
[0.105s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Features.pdb
[0.106s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Features.xml
[0.106s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.FileProviders.Abstractions.dll
[0.106s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.FileProviders.Composite.dll
[0.107s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.FileProviders.Physical.dll
[0.107s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.FileSystemGlobbing.dll
[0.108s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Hosting.Abstractions.dll
[0.108s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Hosting.dll
[0.109s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Logging.Abstractions.dll
[0.109s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Logging.Configuration.dll
[0.110s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Logging.Console.dll
[0.110s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Logging.Debug.dll
[0.111s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Logging.dll
[0.111s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Logging.EventLog.dll
[0.112s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Logging.EventSource.dll
[0.112s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.ObjectPool.dll
[0.113s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.ObjectPool.pdb
[0.113s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.ObjectPool.xml
[0.114s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Options.ConfigurationExtensions.dll
[0.114s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Options.dll
[0.115s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Extensions.Primitives.dll
[0.115s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Net.Http.Headers.dll
[0.116s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Net.Http.Headers.pdb
[0.119s] [....IISExpressDeployer] [Debug]   Copying Microsoft.Net.Http.Headers.xml
[0.119s] [....IISExpressDeployer] [Debug]   Copying System.Diagnostics.EventLog.dll
[0.120s] [....IISExpressDeployer] [Debug]   Copying System.IO.Pipelines.dll
[0.120s] [....IISExpressDeployer] [Debug]   Copying TestTasks.exe
[0.121s] [....IISExpressDeployer] [Debug]   Copying TestTasks.runtimeconfig.json
[0.121s] [....IISExpressDeployer] [Debug]   Copying web.config
[0.122s] [....IISExpressDeployer] [Debug]   Copying xunit.assert.dll
[0.123s] [....IISExpressDeployer] [Information] Attempting to start IIS Express on port: 64860
[0.124s] [....IISExpressDeployer] [Debug] Saving Config to C:\h\w\A924098E\t\tmpxmkaiu.tmp
[0.124s] [....IISExpressDeployer] [Information] Executing command : C:\Program Files\IIS Express\iisexpress.exe /site:HttpTestSite /config:C:\h\w\A924098E\t\tmpxmkaiu.tmp /trace:error /systray:false
[0.124s] [....IISExpressDeployer] [Information] Removing environment variable ASPNETCORE_ENVIRONMENT
[0.124s] [....IISExpressDeployer] [Information] SET ASPNETCORE_DETAILEDERRORS=true
[0.124s] [....IISExpressDeployer] [Information] SET ASPNETCORE_MODULE_DEBUG=console
[0.128s] [....IISExpressDeployer] [Information] iisexpress Process 9140 started
[0.185s] [....IISExpressDeployer] [Information] iisexpress stdout: Starting IIS Express ...
[0.197s] [....IISExpressDeployer] [Information] iisexpress stdout: Initializing the W3 Server Started CTC = 3348875 
[0.202s] [....IISExpressDeployer] [Information] iisexpress stdout: W3 Server initializing WinSock.  CTC = 3348875 
[0.202s] [....IISExpressDeployer] [Information] iisexpress stdout: W3 Server WinSock initialized.  CTC = 3348875 
[0.203s] [....IISExpressDeployer] [Information] iisexpress stdout: W3 Server ThreadPool initialized (ipm has signalled).  CTC = 3348875 
[0.227s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.130Z, PID: 9140] [aspnetcorev2.dll] Initializing logs for 'C:\h\w\A924098E\w\BA950A05\e\ANCM\x64\aspnetcorev2.dll'. Process Id: 9140. File Version: 19.0.23345.0. Description: IIS ASP.NET Core Module V2. Commit: .
[0.227s] [....IISExpressDeployer] [Information] iisexpress stdout: Start listenerChannel http:0
[0.228s] [....IISExpressDeployer] [Information] iisexpress stdout: Successfully registered URL "http://localhost:64860/" for site "HttpTestSite" application "/"
[0.228s] [....IISExpressDeployer] [Information] iisexpress stdout: Registration completed for site "HttpTestSite"
[0.228s] [....IISExpressDeployer] [Information] iisexpress stdout: AppPool 'IISExpressAppPool' initialized
[0.229s] [....IISExpressDeployer] [Information] iisexpress stdout: InitComplete event signalled
[0.229s] [....IISExpressDeployer] [Information] Started iisexpress successfully. Process Id : 9140, Port: 64860
[0.229s] [....IISExpressDeployer] [Information] iisexpress stdout: IIS Express is running.
[0.230s] [....IISExpressDeployer] [Information] Application ready at URL: http://localhost:64860/
[0.231s] [HttpTestSite] [Debug] Method: GET, RequestUri: 'http://localhost:64860/HelloWorld', Version: 1.1, Content: <null>, Headers:
{
}
[0.233s] [....IISExpressDeployer] [Information] iisexpress stdout: IncrementMessages called
[0.234s] [....IISExpressDeployer] [Information] iisexpress stdout: Request started: "GET" http://localhost:64860/HelloWorld
[0.237s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.140Z, PID: 9140] [aspnetcorev2.dll] Resolving hostfxr parameters for application: 'dotnet' arguments: '.\InProcessWebSite.dll CheckOversizedStdOutWrites' path: 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\'
[0.237s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.140Z, PID: 9140] [aspnetcorev2.dll] Known dotnet.exe location: ''
[0.237s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.140Z, PID: 9140] [aspnetcorev2.dll] Process path 'dotnet.exe' is dotnet, treating application as portable
[0.237s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.140Z, PID: 9140] [aspnetcorev2.dll] get_hostfxr_path skipped due to expandedProcessPath being dotnet.exe
[0.238s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.140Z, PID: 9140] [aspnetcorev2.dll] Resolving absolute path to dotnet.exe from 'dotnet.exe'
[0.238s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.140Z, PID: 9140] [aspnetcorev2.dll] Invoking where.exe to find dotnet.exe
[0.303s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.206Z, PID: 9140] [aspnetcorev2.dll] where.exe invocation returned: 'C:\h\w\A924098E\p\dotnet-cli\dotnet.exe
[0.304s] [....IISExpressDeployer] [Information] iisexpress stdout: '
[0.304s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.206Z, PID: 9140] [aspnetcorev2.dll] Current process bitness type detected as isX64=1
[0.304s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.207Z, PID: 9140] [aspnetcorev2.dll] Processing entry 'C:\h\w\A924098E\p\dotnet-cli\dotnet.exe'
[0.306s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.209Z, PID: 9140] [aspnetcorev2.dll] Binary type 6
[0.306s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.209Z, PID: 9140] [aspnetcorev2.dll] Found dotnet.exe via where.exe invocation at 'C:\h\w\A924098E\p\dotnet-cli\dotnet.exe'
[0.306s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.209Z, PID: 9140] [aspnetcorev2.dll] Trying get_hostfxr_path with dotnet path as dotnet root
[0.307s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.209Z, PID: 9140] [aspnetcorev2.dll] hostfxr.dotnet_root: 'C:\h\w\A924098E\p\dotnet-cli'
[0.307s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.209Z, PID: 9140] [aspnetcorev2.dll] hostfxr.assembly_path: 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\'
[0.307s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.210Z, PID: 9140] [aspnetcorev2.dll] dotnetExePath 'C:\h\w\A924098E\p\dotnet-cli\dotnet.exe'
[0.307s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.210Z, PID: 9140] [aspnetcorev2.dll] hostFxrDllpath 'C:\h\w\A924098E\p\dotnet-cli\host\fxr\9.0.0-alpha.1.23606.17\hostfxr.dll'
[0.307s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.210Z, PID: 9140] [aspnetcorev2.dll] Converted argument '.\InProcessWebSite.dll' to 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\.\InProcessWebSite.dll'
[0.307s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.210Z, PID: 9140] [aspnetcorev2.dll] Parsed hostfxr options: dotnet location: 'C:\h\w\A924098E\p\dotnet-cli\dotnet.exe' hostfxr path: 'C:\h\w\A924098E\p\dotnet-cli\host\fxr\9.0.0-alpha.1.23606.17\hostfxr.dll' arguments:
[0.307s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.210Z, PID: 9140] [aspnetcorev2.dll] Argument[0] = 'C:\h\w\A924098E\p\dotnet-cli\dotnet.exe'
[0.307s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.210Z, PID: 9140] [aspnetcorev2.dll] Argument[1] = 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\.\InProcessWebSite.dll'
[0.307s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.210Z, PID: 9140] [aspnetcorev2.dll] Argument[2] = 'CheckOversizedStdOutWrites'
[0.307s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.210Z, PID: 9140] [aspnetcorev2.dll] Loading hostfxr from location C:\h\w\A924098E\p\dotnet-cli\host\fxr\9.0.0-alpha.1.23606.17\hostfxr.dll
[0.322s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.224Z, PID: 9140] [aspnetcorev2.dll] Canceling standard stream pipe reader
[0.322s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.225Z, PID: 9140] [aspnetcorev2.dll] Loading request handler:  'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\x64\aspnetcorev2_inprocess.dll'
[0.340s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.242Z, PID: 9140] [aspnetcorev2_inprocess.dll] Initializing logs for 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\x64\aspnetcorev2_inprocess.dll'. Process Id: 9140. File Version: 19.0.23345.0. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: .
[0.340s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.242Z, PID: 9140] [aspnetcorev2.dll] Creating handler application
[0.340s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.243Z, PID: 9140] [aspnetcorev2_inprocess.dll] Waiting for initialization
[0.340s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.243Z, PID: 9140] [aspnetcorev2_inprocess.dll] Starting app_offline monitoring in application 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\'
[0.340s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.243Z, PID: 9140] [aspnetcorev2_inprocess.dll] Starting file watcher thread
[0.340s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.243Z, PID: 9140] [aspnetcorev2_inprocess.dll] Starting in-process worker thread
[0.340s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.243Z, PID: 9140] [aspnetcorev2_inprocess.dll] Resolving hostfxr parameters for application: 'dotnet' arguments: '.\InProcessWebSite.dll CheckOversizedStdOutWrites' path: 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\'
[0.340s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.243Z, PID: 9140] [aspnetcorev2_inprocess.dll] Known dotnet.exe location: 'C:\h\w\A924098E\p\dotnet-cli\dotnet.exe'
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.243Z, PID: 9140] [aspnetcorev2_inprocess.dll] Process path 'dotnet.exe' is dotnet, treating application as portable
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.243Z, PID: 9140] [aspnetcorev2_inprocess.dll] Trying get_hostfxr_path with dotnet path as dotnet root
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.243Z, PID: 9140] [aspnetcorev2_inprocess.dll] hostfxr.dotnet_root: 'C:\h\w\A924098E\p\dotnet-cli'
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.243Z, PID: 9140] [aspnetcorev2_inprocess.dll] hostfxr.assembly_path: 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\'
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] dotnetExePath 'C:\h\w\A924098E\p\dotnet-cli\dotnet.exe'
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] hostFxrDllpath 'C:\h\w\A924098E\p\dotnet-cli\host\fxr\9.0.0-alpha.1.23606.17\hostfxr.dll'
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] Converted argument '.\InProcessWebSite.dll' to 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\.\InProcessWebSite.dll'
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] Parsed hostfxr options: dotnet location: 'C:\h\w\A924098E\p\dotnet-cli\dotnet.exe' hostfxr path: 'C:\h\w\A924098E\p\dotnet-cli\host\fxr\9.0.0-alpha.1.23606.17\hostfxr.dll' arguments:
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] Argument[0] = 'C:\h\w\A924098E\p\dotnet-cli\dotnet.exe'
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] Argument[1] = 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\.\InProcessWebSite.dll'
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] Argument[2] = 'CheckOversizedStdOutWrites'
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] Setting environment variable ASPNETCORE_IIS_HTTPAUTH=windows;anonymous;
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] Setting environment variable ASPNETCORE_IIS_PHYSICAL_PATH=C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] Loading hostfxr from location C:\h\w\A924098E\p\dotnet-cli\host\fxr\9.0.0-alpha.1.23606.17\hostfxr.dll
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] Initial Dll directory: 'C:\Program Files\IIS Express', current directory: 'C:\Program Files\IIS Express'
[0.341s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.244Z, PID: 9140] [aspnetcorev2_inprocess.dll] Setting current directory to C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\
[0.694s] [....IISExpressDeployer] [Information] iisexpress stdout: aaaa[SNIP]
[0.694s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.597Z, PID: 9140] [aspnetcorev2_inprocess.dll] Managed application exited with code 12
[0.694s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.597Z, PID: 9140] [aspnetcorev2_inprocess.dll] Starting shutdown sequence 1
[0.694s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.597Z, PID: 9140] [aspnetcorev2_inprocess.dll] Clr thread wait ended: clrThreadExited: 1
[0.696s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.598Z, PID: 9140] [aspnetcorev2_inprocess.dll] Event Log: 'Application '/LM/W3SVC/1/ROOT' with physical root 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\' has exited from Program.Main with exit code = '12'. First 30KB characters of captured stdout and stderr logs:
[0.696s] [....IISExpressDeployer] [Information] iisexpress stdout: aaaa[SNIP]' 
[0.696s] [....IISExpressDeployer] [Information] iisexpress stdout: End Event Log Message.
[0.696s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.599Z, PID: 9140] [aspnetcorev2_inprocess.dll] Canceling standard stream pipe reader
[0.696s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.599Z, PID: 9140] [aspnetcorev2_inprocess.dll] Stopping in-process worker thread
[0.696s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.599Z, PID: 9140] [aspnetcorev2_inprocess.dll] Stopping CLR
[0.697s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.599Z, PID: 9140] [aspnetcorev2_inprocess.dll] Event Log: 'Application '/LM/W3SVC/1/ROOT' with physical root 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\' failed to load coreclr. Exception message:
[0.697s] [....IISExpressDeployer] [Information] iisexpress stdout: CLR worker thread exited prematurely' 
[0.697s] [....IISExpressDeployer] [Information] iisexpress stdout: End Event Log Message.
[0.697s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.600Z, PID: 9140] [aspnetcorev2_inprocess.dll] InvalidOperationException 'CLR worker thread exited prematurely' caught at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\InProcessRequestHandler\inprocessapplication.cpp:489 
[0.697s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.600Z, PID: 9140] [aspnetcorev2_inprocess.dll] Failed HRESULT returned: 0x8007023e at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\InProcessRequestHandler\dllmain.cpp:131 
[0.697s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.600Z, PID: 9140] [aspnetcorev2_inprocess.dll] Starting app_offline monitoring in application 'C:\h\w\A924098E\t\654257c4e04a4de1ab0c0df9bed3adea\'
[0.697s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.600Z, PID: 9140] [aspnetcorev2_inprocess.dll] Starting file watcher thread
[0.697s] [....IISExpressDeployer] [Information] iisexpress stdout: Request ended: http://localhost:64860/HelloWorld with HTTP status 500.30
[0.698s] [HttpTestSite] [Warning] StatusCode: 500, ReasonPhrase: 'Internal Server Error', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Server: Microsoft-IIS/10.0
  X-SourceFiles: =?UTF-8?B?QzpcaFx3XEE5MjQwOThFXHRcNjU0MjU3YzRlMDRhNGRlMWFiMGMwZGY5YmVkM2FkZWFcSGVsbG9Xb3JsZA==?=
  X-Powered-By: ASP.NET
  Date: Mon, 11 Dec 2023 14:43:02 GMT
  Content-Type: text/html
  Content-Length: 2416
}
[0.698s] [HttpTestSite] [Warning] <!DOCTYPE html>
<html lang="en-US" xmlns="http://www.w3.org/1999/xhtml">
    <head>
        <meta charset="utf-8" />
        <title> HTTP Error 500.30 - ASP.NET Core app failed to start </title>
        <style>
            body {
                font-family: 'Segoe UI', Tahoma, Arial, Helvetica, sans-serif;
                font-size: .813em;
                color: #222;
                background-color: #fff;
            }

            h1, h2, h3, h4, h5 {
                /*font-family: 'Segoe UI',Tahoma,Arial,Helvetica,sans-serif;*/
                font-weight: 100;
            }

            h1 {
                color: #44525e;
                margin: 15px 0 15px 0;
            }

            h2 {
                margin: 10px 5px 0 0;
            }

            h3 {
                color: #363636;
                margin: 5px 5px 0 0;
            }

            code {
                font-family: Consolas, "Courier New", courier, monospace;
            }

            body .titleerror {
                padding: 3px 3px 6px 3px;
                display: block;
                font-size: 1.5em;
                font-weight: 100;
            }

            a {
                color: #1ba1e2;
                text-decoration: none;
            }

                a:hover {
                    color: #13709e;
                    text-decoration: underline;
                }

            li {
                margin: 5px;
            }

        </style>
    </head>
    <body>
        <h1> HTTP Error 500.30 - ASP.NET Core app failed to start </h1>

        <h2> Common solutions to this issue: </h2><ul><li>The app failed to start</li><li>The app started but then stopped</li><li>The app started but threw an exception during startup</li></ul>

        

        <h2> Troubleshooting steps: </h2>
        <ul>
            <li> Check the system event log for error messages </li>
            <li> Enable logging the application process' stdout messages </li>
            <li> Attach a debugger to the application process and inspect </li>
        </ul>

        <h2>
            For more guidance on diagnosing and handling these errors, visit
             <a href="https://go.microsoft.com/fwlink/?LinkID=2028526"> <cite>Troubleshoot ASP.NET Core on Azure App Service and IIS</cite></a>.
        </h2>
    </body>
</html>

[0.699s] [....IISExpressDeployer] [Information] Sending shutdown request to 9140
[0.700s] [....IISExpressDeployer] [Information] iisexpress stdout: Stopping IIS Express ...
[0.700s] [....IISExpressDeployer] [Information] iisexpress stdout: Process Model Shutdown called
[0.813s] [....IISExpressDeployer] [Information] iisexpress stdout: Stop listenerChannel http:0
[0.813s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.716Z, PID: 9140] [aspnetcorev2.dll] ASPNET_CORE_GLOBAL_MODULE::OnGlobalStopListening
[0.813s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.716Z, PID: 9140] [aspnetcorev2.dll] Stopping application '/LM/W3SVC/1/ROOT'
[0.813s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.716Z, PID: 9140] [aspnetcorev2_inprocess.dll] Stopping file watching.
[0.813s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.716Z, PID: 9140] [aspnetcorev2_inprocess.dll] Stopping file watcher thread
[0.813s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.716Z, PID: 9140] [aspnetcorev2_inprocess.dll] Waiting for file watcher thread to exit.
[0.814s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.716Z, PID: 9140] [aspnetcorev2_inprocess.dll] Waiting for file watcher thread to exit.
[0.814s] [....IISExpressDeployer] [Information] iisexpress stdout: Terminating W3_SERVER object
[0.923s] [....IISExpressDeployer] [Information] iisexpress stdout: [2023-12-11T14:43:02.826Z, PID: 9140] [aspnetcorev2.dll] ASPNET_CORE_GLOBAL_MODULE::Terminate
[1.016s] [....IISExpressDeployer] [Information] iisexpress stdout: Waiting for all LISTENER_CHANNELS to stop
[1.219s] [....IISExpressDeployer] [Information] iisexpress stdout: Waiting for all LISTENER_CHANNELS to stop
[1.422s] [....IISExpressDeployer] [Information] iisexpress stdout: Waiting for all LISTENER_CHANNELS to stop
[1.625s] [....IISExpressDeployer] [Information] iisexpress stdout: Waiting for all LISTENER_CHANNELS to stop
[1.829s] [....IISExpressDeployer] [Information] iisexpress stdout: Waiting for all LISTENER_CHANNELS to stop
[2.032s] [....IISExpressDeployer] [Information] iisexpress stdout: Waiting for all LISTENER_CHANNELS to stop
[2.033s] [....IISExpressDeployer] [Information] iisexpress stdout: IIS Express stopped.
[2.041s] [....IISExpressDeployer] [Information] iisexpress Process 9140 shut down
[2.048s] [....IISExpressDeployer] [Information] Host process shutting down.
[2.048s] [....IISExpressDeployer] [Debug] Deleting applicationHost.config file from C:\h\w\A924098E\t\tmpxmkaiu.tmp
[2.075s] [....IISExpressDeployer] [Information] [Time]: Total time taken for this test variation '2.0685916' seconds

Note: I trimmed the namespace of IISExpressDeployer and the very long strings of aaaa.

Build

https://dev.azure.com/dnceng-public/public/_build/results?buildId=495416

Metadata

Metadata

Assignees

No one assigned

    Labels

    area-networkingIncludes servers, yarp, json patch, bedrock, websockets, http client factory, and http abstractionsfeature-iisIncludes: IIS, ANCMtest-failure

    Type

    No type

    Projects

    No projects

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions