aspnet core 3.1 in-process hosting hitting 500.37 ANCM startup timeout.

[dxynnez]

Describe the bug

We have aspnet core 3.1 apps running on Azure App Service recently hit the 500.37 ANCM timeout problem. According to the doc and this, for in-process hosting model, the ANCM should never timeout and should just keep waiting. Is it a bug or our configuration has some problems? FYI, our app was published as self-contained platform dependent (win10-x64).

Following is the corresponding event log:

<Event>
<System>
<Provider Name="IIS AspNetCore Module V2"/>
<EventID>1007</EventID>
<Level>1</Level>
<Task>0</Task>
<Keywords>Keywords</Keywords>
<TimeCreated SystemTime="2020-09-04T11:36:15Z"/>
<EventRecordID>2002578</EventRecordID>
<Channel>Application</Channel>
<Computer>RD0003FF9B1D26</Computer>
<Security/>
</System>
<EventData>
<Data>Application '/LM/W3SVC/101432053/ROOT' with physical root 'D:\home\site\wwwroot\' failed to load coreclr. Exception message: Managed server didn't initialize after 120000 ms.</Data>
<Data>Process Id: 13856.</Data>
<Data>File Version: 13.1.20074.3. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: e81033e094d4663ffd227bb4aed30b76b0631e6d</Data>
</EventData>
</Event>

This is our web.config file:

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <location path="." inheritInChildApplications="false">
    <system.webServer>
      <handlers>
        <add name="aspNetCore" path="*" verb="*" modules="AspNetCoreModuleV2" resourceType="Unspecified" />
      </handlers>
      <aspNetCore processPath="**************" stdoutLogEnabled="false" stdoutLogFile=".\logs\stdout" hostingModel="inprocess" />
    </system.webServer>
  </location>
</configuration>

And here are some other info that might help with diagnosing the problem:

OS version: Microsoft Windows NT 10.0.14393.0
64 bit system: True
64 bit process: True
Processor count: 4
CLR version: 4.0.30319.42000
System directory: D:\Windows\system32
Current working directory: D:\Windows\system32
IIS command line: D:\Windows\system32\inetsrv\w3wp.exe -ap "*******" -v "v4.0" -a "\\.\pipe\iisipm0cdc315a-b625-4da1-a72e-519e4c2c86e0" -h "C:\DWASFiles\Sites\******\Config\applicationhost.config" -w "C:\DWASFiles\Sites\*******\Config\rootweb.config" -m 0

.NET Core SDK (reflecting any global.json):
 Version:   3.1.302
 Commit:    41faccf259

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.14393
 OS Platform: Windows
 RID:         win10-x86
 Base Path:   D:\Program Files (x86)\dotnet\sdk\3.1.302\

Host (useful for support):
  Version: 3.1.6
  Commit:  3acd9b0cd1

.NET Core SDKs installed:
  1.1.14 [D:\Program Files (x86)\dotnet\sdk]
  2.1.516 [D:\Program Files (x86)\dotnet\sdk]
  2.2.109 [D:\Program Files (x86)\dotnet\sdk]
  3.1.302 [D:\Program Files (x86)\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.19 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.20 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.2.8 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.2.11 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.19 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.20 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.2.8 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.2.11 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.0.3 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.5 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.6 [D:\Program Files (x86)\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 1.0.16 [D:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.1.13 [D:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.9 [D:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.20 [D:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.2.11 [D:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.0.3 [D:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.6 [D:\Program Files (x86)\dotnet\shared\Microsoft.NETCore.App]

To Reproduce

I can't really reproduce it as the restart was triggered by azure infra upgrade, normally the app startup pretty fast. Would simply let my startup sleep for more than the default startupTimeLimit (120s) trigger the ANCM failure again?

Exceptions (if any)

Application '/LM/W3SVC/101432053/ROOT' with physical root 'D:\home\site\wwwroot' failed to load coreclr. Exception message:
Managed server didn't initialize after 120000 ms.
Process Id: 13856.
File Version: 13.1.20074.3. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: e81033e

Any help would be greatly appreciated. Please do let me know if the issue should be created at the App service side directly. Thanks!

[BrennanConroy]

Would simply let my startup sleep for more than the default startupTimeLimit (120s) trigger the ANCM failure again?

Yes, there is a startup time limit. You can configure it by setting the startupTimeLimit, https://docs.microsoft.com/aspnet/core/host-and-deploy/aspnet-core-module?view=aspnetcore-3.1#attributes-of-the-aspnetcore-element
So if your app starts too slowly you'll see this.

Also, take a look at #25321 which fixed some issues with app startup.

[dxynnez]

Thanks @BrennanConroy for you response so much! I actually came from the link you sent, on the top of the page, it actually says:

The requestTimeout attribute doesn't apply to in-process hosting.

And the answer to THIS issue seems to imply the same thing - For in-process hosting, ANCM would not timeout and would just keeping waiting.

Did I misunderstand the doc?

Also, I see that the fix was merged into 5.0-rc2 (I am assuming it's for .NET 5.0), is there any chance that it would be back ported into netcore 3.x?

[BrennanConroy]

requestTimeout is not the same as startupTimeLimit.

Also, I see that the fix was merged into 5.0-rc2 (I am assuming it's for .NET 5.0), is there any chance that it would be back ported into netcore 3.x?

Unlikely, if you can reliably reproduce the issue and then switch to 5.0 and the issue goes away that would help though.

[dxynnez]

@BrennanConroy aha, dumb like me...Thanks so much! I think the first thing I will do is to increase the limit then.

The fix seems to be promising and I can definitely try it out. Just want to confirm, if I simply put a sleep inside the program#main, I should be able to reproduce it, correct?

[BrennanConroy]

if I simply put a sleep inside the program#main, I should be able to reproduce it, correct?

Yes