IIS tests are timing out

[HaoK]

Failing Test(s)

• Microsoft.AspNetCore.Server.IIS.FunctionalTests.StartupTests.StartupTimeoutIsApplied

Error Message

[xUnit.net 00:37:57.69] IIS.FunctionalTests: [Long Running Test] 'Microsoft.AspNetCore.Server.IIS.FunctionalTests.StartupTests.StartupTimeoutIsApplied', Elapsed: 00:01:01

Stacktrace

Logs

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-heads-main-4c1249124fe444a7a4/IIS.FunctionalTests--net7.0/1/console.a5f2a058.log?sv=2019-07-07&se=2021-11-17T16%3A45%3A05Z&sr=c&sp=rl&sig=NdiB0pT0IoDtqVqErQu47eiso%2BOwkbPETL70HkXum2w%3D

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-aspnetcore-refs-heads-main-7dbe5a6acd384f8cb5/IIS.FunctionalTests--net7.0/1/console.8b7ec6e2.log?sv=2019-07-07&se=2021-11-17T18%3A22%3A00Z&sr=c&sp=rl&sig=3vE%2FoBIyCGQVirD0aYEiW1GC5VHX3Tuu%2BNZPbSe1eUU%3D

https://dev.azure.com/dnceng/public/_build/results?buildId=1444604
https://dev.azure.com/dnceng/public/_build/results?buildId=1444750

Test.log added to details

[0.001s] [TestLifetime] [Information] Starting test StartupTimeoutIsApplied at 2021-10-28T18:56:51
[0.004s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Deploying [Variation] :: ServerType=IIS, Runtime=CoreClr, Arch=x64, BaseUrlHint=, Publish=True
[0.004s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Microsoft Windows NT 10.0.22000.0
[0.004s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Using prepublished application from C:\h\w\BF4609DC\w\B0B50971\e\InProcessWebSite-Portable
[0.006s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug] Processing C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\runtimes\win\lib\net7.0
[0.006s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying System.Diagnostics.EventLog.dll
[0.006s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying System.Diagnostics.EventLog.Messages.dll
[0.007s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug] Processing C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\runtimes\win\lib
[0.007s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug] Processing C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\runtimes\win
[0.007s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug] Processing C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\runtimes
[0.008s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug] Processing C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\wwwroot
[0.008s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying static.txt
[0.008s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug] Processing C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\x64
[0.009s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying aspnetcorev2_inprocess.dll
[0.009s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug] Processing C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\x86
[0.009s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying aspnetcorev2_inprocess.dll
[0.010s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug] Processing C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72
[0.010s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying InProcessWebSite.deps.json
[0.011s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying InProcessWebSite.dll
[0.011s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying InProcessWebSite.exe
[0.012s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying InProcessWebSite.pdb
[0.012s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying InProcessWebSite.runtimeconfig.json
[0.012s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Abstractions.dll
[0.013s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Abstractions.pdb
[0.013s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Abstractions.xml
[0.014s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Core.dll
[0.014s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Core.pdb
[0.015s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Authentication.Core.xml
[0.015s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Connections.Abstractions.dll
[0.015s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Connections.Abstractions.pdb
[0.016s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Connections.Abstractions.xml
[0.016s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Abstractions.dll
[0.017s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Abstractions.pdb
[0.017s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Abstractions.xml
[0.018s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.dll
[0.018s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.pdb
[0.018s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Server.Abstractions.dll
[0.019s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Server.Abstractions.pdb
[0.019s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.Server.Abstractions.xml
[0.020s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Hosting.xml
[0.020s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Abstractions.dll
[0.021s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Abstractions.pdb
[0.021s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Abstractions.xml
[0.022s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.dll
[0.022s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Extensions.dll
[0.023s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Extensions.pdb
[0.023s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Extensions.xml
[0.024s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Features.dll
[0.024s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Features.pdb
[0.025s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.Features.xml
[0.025s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.pdb
[0.025s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Http.xml
[0.026s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpOverrides.dll
[0.027s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpOverrides.pdb
[0.027s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpOverrides.xml
[0.028s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpsPolicy.dll
[0.028s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpsPolicy.pdb
[0.029s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.HttpsPolicy.xml
[0.029s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.ResponseCompression.dll
[0.029s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.ResponseCompression.pdb
[0.030s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.ResponseCompression.xml
[0.030s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IIS.dll
[0.031s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IIS.pdb
[0.031s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IIS.xml
[0.032s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IISIntegration.dll
[0.032s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IISIntegration.pdb
[0.033s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.IISIntegration.xml
[0.033s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Core.dll
[0.034s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Core.pdb
[0.035s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Core.xml
[0.035s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.dll
[0.036s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.pdb
[0.036s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.dll
[0.037s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.pdb
[0.037s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.xml
[0.037s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.dll
[0.038s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.pdb
[0.038s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.xml
[0.039s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.Server.Kestrel.xml
[0.039s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.WebUtilities.dll
[0.040s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.WebUtilities.pdb
[0.040s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.AspNetCore.WebUtilities.xml
[0.041s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.Abstractions.dll
[0.041s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.Binder.dll
[0.041s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.CommandLine.dll
[0.042s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.dll
[0.042s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.EnvironmentVariables.dll
[0.043s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.FileExtensions.dll
[0.043s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.Json.dll
[0.044s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Configuration.UserSecrets.dll
[0.044s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.DependencyInjection.Abstractions.dll
[0.045s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.DependencyInjection.dll
[0.045s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Features.dll
[0.045s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Features.pdb
[0.046s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Features.xml
[0.046s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.FileProviders.Abstractions.dll
[0.047s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.FileProviders.Composite.dll
[0.047s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.FileProviders.Physical.dll
[0.047s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.FileSystemGlobbing.dll
[0.048s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Hosting.Abstractions.dll
[0.048s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Hosting.dll
[0.049s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Logging.Abstractions.dll
[0.049s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Logging.Configuration.dll
[0.050s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Logging.Console.dll
[0.050s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Logging.Debug.dll
[0.051s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Logging.dll
[0.051s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Logging.EventLog.dll
[0.051s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Logging.EventSource.dll
[0.052s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.ObjectPool.dll
[0.052s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.ObjectPool.pdb
[0.053s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.ObjectPool.xml
[0.053s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Options.ConfigurationExtensions.dll
[0.053s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Options.dll
[0.054s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Extensions.Primitives.dll
[0.054s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Net.Http.Headers.dll
[0.055s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Net.Http.Headers.pdb
[0.055s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying Microsoft.Net.Http.Headers.xml
[0.056s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying System.Diagnostics.EventLog.dll
[0.056s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying System.IO.Pipelines.dll
[0.056s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying web.config
[0.057s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Debug]   Copying xunit.assert.dll
[0.061s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] applicationhost.config path C:\h\w\BF4609DC\t\b6a9604b-b6df-43ac-87d4-c41ee4e0b446
[0.255s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] W3SVC status Running
[0.268s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Starting pool, state: Started
[0.271s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Starting site, state: Started
[0.388s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Site has started.
[0.389s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Successfully finished IIS application directory setup.
[0.390s] [HttpTestSite] [Debug] Method: GET, RequestUri: 'http://localhost:58938/', Version: 1.1, Content: <null>, Headers:
{
}
[3.184s] [HttpTestSite] [Warning] StatusCode: 500, ReasonPhrase: 'Internal Server Error', Version: 1.1, Content: System.Net.Http.HttpConnectionResponseContent, Headers:
{
  Server: Microsoft-IIS/10.0
  Date: Thu, 28 Oct 2021 18:56:55 GMT
  Content-Type: text/html
  Content-Length: 2339
}
[3.185s] [HttpTestSite] [Warning] <!DOCTYPE html>
<html lang="en-US" xmlns="http://www.w3.org/1999/xhtml">
    <head>
        <meta charset="utf-8" />
        <title> HTTP Error 500.37 - ASP.NET Core app failed to start within startup time limit </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.37 - ASP.NET Core app failed to start within startup time limit </h1>

        <h2> Common solutions to this issue: </h2>ASP.NET Core app failed to start after 1000 milliseconds

        

        <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 information visit:
             <a href="https://go.microsoft.com/fwlink/?LinkID=2028265"> <cite> https://go.microsoft.com/fwlink/?LinkID=2028265 </cite></a>
        </h2>

    </body>
</html>

[77.491s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Stopping site, state: Stopped
[77.494s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Stopping pool, state: Stopping
[80.863s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Site has stopped successfully.
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Host process shutting down.
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:52.377Z, PID: 6332] [aspnetcorev2.dll] Initializing logs for 'C:\h\w\BF4609DC\w\B0B50971\e\ANCM\x64\aspnetcorev2.dll'. Process Id: 6332. File Version: 17.0.21301.0. Description: IIS ASP.NET Core Module V2. Commit: a262df2273859a2f69915477b3ae1b948c077ac2.
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:52.495Z, PID: 6332] [aspnetcorev2.dll] Resolving hostfxr parameters for application: 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe' arguments: '.\InProcessWebSite.dll Hang' path: 'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\'
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:52.622Z, PID: 6332] [aspnetcorev2.dll] Known dotnet.exe location: ''
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:52.843Z, PID: 6332] [aspnetcorev2.dll] Process path 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe' is dotnet, treating application as portable
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:52.949Z, PID: 6332] [aspnetcorev2.dll] Resolving absolute path to dotnet.exe from 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe'
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.008Z, PID: 6332] [aspnetcorev2.dll] Found dotnet.exe at 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe'
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.059Z, PID: 6332] [aspnetcorev2.dll] Resolving absolute path to hostfxr.dll from 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe'
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.091Z, PID: 6332] [aspnetcorev2.dll] hostfxr.dll located at 'C:\h\w\BF4609DC\p\dotnet-cli\host\fxr\7.0.0-alpha.1.21528.1\hostfxr.dll'
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.125Z, PID: 6332] [aspnetcorev2.dll] Converted argument '.\InProcessWebSite.dll' to 'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\.\InProcessWebSite.dll'
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.149Z, PID: 6332] [aspnetcorev2.dll] Parsed hostfxr options: dotnet location: 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe' hostfxr path: 'C:\h\w\BF4609DC\p\dotnet-cli\host\fxr\7.0.0-alpha.1.21528.1\hostfxr.dll' arguments:
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.178Z, PID: 6332] [aspnetcorev2.dll] Argument[0] = 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe'
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.212Z, PID: 6332] [aspnetcorev2.dll] Argument[1] = 'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\.\InProcessWebSite.dll'
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.243Z, PID: 6332] [aspnetcorev2.dll] Argument[2] = 'Hang'
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.279Z, PID: 6332] [aspnetcorev2.dll] Loading hostfxr from location C:\h\w\BF4609DC\p\dotnet-cli\host\fxr\7.0.0-alpha.1.21528.1\hostfxr.dll
[80.984s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.345Z, PID: 6332] [aspnetcorev2.dll] Canceling standard stream pipe reader
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.373Z, PID: 6332] [aspnetcorev2.dll] Loading request handler:  'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\x64\aspnetcorev2_inprocess.dll'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.408Z, PID: 6332] [aspnetcorev2.dll] Creating handler application
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.442Z, PID: 6332] [aspnetcorev2_inprocess.dll] Initializing logs for 'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\x64\aspnetcorev2_inprocess.dll'. Process Id: 6332. File Version: 17.0.21301.0. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: a262df2273859a2f69915477b3ae1b948c077ac2.
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.478Z, PID: 6332] [aspnetcorev2_inprocess.dll] Waiting for initialization
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.512Z, PID: 6332] [aspnetcorev2_inprocess.dll] Starting app_offline monitoring in application 'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.540Z, PID: 6332] [aspnetcorev2_inprocess.dll] Starting file watcher thread
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.540Z, PID: 6332] [aspnetcorev2_inprocess.dll] Starting in-process worker thread
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.589Z, PID: 6332] [aspnetcorev2_inprocess.dll] Resolving hostfxr parameters for application: 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe' arguments: '.\InProcessWebSite.dll Hang' path: 'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.618Z, PID: 6332] [aspnetcorev2_inprocess.dll] Known dotnet.exe location: 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.647Z, PID: 6332] [aspnetcorev2_inprocess.dll] Process path 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe' is dotnet, treating application as portable
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.688Z, PID: 6332] [aspnetcorev2_inprocess.dll] Resolving absolute path to hostfxr.dll from 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.721Z, PID: 6332] [aspnetcorev2_inprocess.dll] hostfxr.dll located at 'C:\h\w\BF4609DC\p\dotnet-cli\host\fxr\7.0.0-alpha.1.21528.1\hostfxr.dll'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.756Z, PID: 6332] [aspnetcorev2_inprocess.dll] Converted argument '.\InProcessWebSite.dll' to 'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\.\InProcessWebSite.dll'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.787Z, PID: 6332] [aspnetcorev2_inprocess.dll] Parsed hostfxr options: dotnet location: 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe' hostfxr path: 'C:\h\w\BF4609DC\p\dotnet-cli\host\fxr\7.0.0-alpha.1.21528.1\hostfxr.dll' arguments:
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.827Z, PID: 6332] [aspnetcorev2_inprocess.dll] Argument[0] = 'C:\h\w\BF4609DC\p\dotnet-cli\dotnet.exe'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.858Z, PID: 6332] [aspnetcorev2_inprocess.dll] Argument[1] = 'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\.\InProcessWebSite.dll'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.909Z, PID: 6332] [aspnetcorev2_inprocess.dll] Argument[2] = 'Hang'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:53.954Z, PID: 6332] [aspnetcorev2_inprocess.dll] Setting environment variable ASPNETCORE_DETAILEDERRORS=true
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.023Z, PID: 6332] [aspnetcorev2_inprocess.dll] Setting environment variable ASPNETCORE_IIS_HTTPAUTH=anonymous;
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.084Z, PID: 6332] [aspnetcorev2_inprocess.dll] Setting environment variable ASPNETCORE_IIS_PHYSICAL_PATH=C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.138Z, PID: 6332] [aspnetcorev2_inprocess.dll] Loading hostfxr from location C:\h\w\BF4609DC\p\dotnet-cli\host\fxr\7.0.0-alpha.1.21528.1\hostfxr.dll
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.185Z, PID: 6332] [aspnetcorev2_inprocess.dll] Initial Dll directory: '', current directory: 'c:\windows\system32\inetsrv'
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.257Z, PID: 6332] [aspnetcorev2_inprocess.dll] Setting dll directory to c:\windows\system32\inetsrv
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.314Z, PID: 6332] [aspnetcorev2_inprocess.dll] Setting current directory to C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.550Z, PID: 6332] [aspnetcorev2_inprocess.dll] Stopping file watching.
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.608Z, PID: 6332] [aspnetcorev2_inprocess.dll] Stopping file watcher thread
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.652Z, PID: 6332] [aspnetcorev2_inprocess.dll] Stopping CLR
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.697Z, PID: 6332] [aspnetcorev2_inprocess.dll] Starting shutdown sequence 0
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.751Z, PID: 6332] [aspnetcorev2_inprocess.dll] Clr thread wait ended: clrThreadExited: 0
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.819Z, PID: 6332] [aspnetcorev2_inprocess.dll] Event Log: 'Failed to gracefully shutdown application 'MACHINE/WEBROOT/APPHOST/DEFAULT WEB SITE'.' 
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] End Event Log Message.
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.860Z, PID: 6332] [aspnetcorev2_inprocess.dll] Canceling standard stream pipe reader
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.901Z, PID: 6332] [aspnetcorev2_inprocess.dll] Stopping in-process worker thread
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:54.950Z, PID: 6332] [aspnetcorev2_inprocess.dll] AspNetCore InProcess Recycle Process on Demand
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:55.001Z, PID: 6332] [aspnetcorev2_inprocess.dll] Event Log: 'Application '/LM/W3SVC/1/ROOT' with physical root 'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\' failed to load coreclr. Exception message:
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] Managed server didn't initialize after 1000 ms.' 
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] End Event Log Message.
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:55.039Z, PID: 6332] [aspnetcorev2_inprocess.dll] InvalidOperationException 'Managed server didn't initialize after 1000 ms.' caught at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\InProcessRequestHandler\inprocessapplication.cpp:489 
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:55.051Z, PID: 6332] [aspnetcorev2.dll] ASPNET_CORE_GLOBAL_MODULE::OnGlobalStopListening
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:55.084Z, PID: 6332] [aspnetcorev2_inprocess.dll] Failed HRESULT returned: 0x8007023e at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\InProcessRequestHandler\dllmain.cpp:131 
[80.985s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:55.131Z, PID: 6332] [aspnetcorev2_inprocess.dll] Starting app_offline monitoring in application 'C:\h\w\BF4609DC\t\f3bf46ffe0f34dc39a9b96a7fa343f72\'
[80.986s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:55.167Z, PID: 6332] [aspnetcorev2.dll] Stopping application '/LM/W3SVC/1/ROOT'
[80.986s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:55.167Z, PID: 6332] [aspnetcorev2_inprocess.dll] Starting file watcher thread
[80.986s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:55.203Z, PID: 6332] [aspnetcorev2_inprocess.dll] Stopping file watching.
[80.986s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:56:55.232Z, PID: 6332] [aspnetcorev2_inprocess.dll] Stopping file watcher thread
[80.986s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [2021-10-28T18:58:08.135Z, PID: 6332] [aspnetcorev2.dll] ASPNET_CORE_GLOBAL_MODULE::Terminate
[81.241s] [Microsoft.AspNetCore.Server.IntegrationTesting.IIS.IISDeployer] [Information] [Time]: Total time taken for this test variation '81.2361867' seconds

Build

[HaoK]

Not sure if this is just due to not waiting long enough before considering a test hung?

[Tratcher]

Copy the logs into the issue so they don't get deleted.

[HaoK]

Ah good idea, done

[HaoK]

Seems like we were hitting the job timeout instead of any individual test timing out, should revisit and audit the total tests

[HaoK]

Fixed immediate issue of timeouts by restoring and upping the custom helix job to 1:15, but will keep this open to see if we can trim some test time

[HaoK]

Long running tests:

StartupTimeoutIsApplied [1 m 20 s]
ShutdownTests.ConfigurationChangeStopsInProcess [1 m 22 s]
AppOfflineDroppedWhileSiteFailedToStartInRequestHandler_SiteStops_InProcess [1 m 20 s]
AppOfflineDroppedWhileSiteRunning_SiteShutsDown_InProcess [1 m 21 s]
CallStopAsyncOnRequestThread_DoesNotHangIndefinitely(path: "/ShutdownStopAsyncWithCancelledToken") [1 m 20 s]
CallStopAsyncOnRequestThread_DoesNotHangIndefinitely(path: "/ShutdownStopAsync") [1 m 20 s]
GracefulShutdownWorksWithMultipleRequestsInFlight_InProcess [1 m 35 s]
ShadowCopyCleansUpOlderFolders [1 m 25 s]
ShadowCopyE2EWorksWithFolderPresent [1 m 21 s]
ShadowCopySingleFileChangedWorks [1 m 24 s]
ShadowCopyE2EWorksWithOldFoldersPresent [2 m 11 s]

[HaoK]

After talking with Matt, looks like IIS.FunctionalTests are the long pole, if we can split it in half this would actually potentially cut 15 minutes out of our PRs