Azure App Service & ASP.NET Core 3.1 500.30 - One odd cause

Summary

The problem in this case was, somehow, being caused by the customer's App Service having the .NET Core 3.1 runtime installed via Site Extension, instead of using the built-in runtime that comes with App Services.

The issue resolved when the Site Extension was removed, and the App Service was stopped and re-started.

Deeper Dive into the Data

This issue showed different symptoms depending on whether the ASP.NET Core app was running in-process or out-of-process.

In-Process

In-process, the symptom was a 500.30 In-Process Start Failure with error code 8007023e. This exception code means "unhandled exception." Viewing the eventlog.xml in the App Service via Kudu came up with this couplet of events every time:

<Event>

<System>

<Provider Name="IIS AspNetCore Module V2"/>

<EventID>1018</EventID>

<Level>1</Level>

<Task>0</Task>

<Keywords>Keywords</Keywords>

<TimeCreated SystemTime="2023-01-03T16:23:05Z"/>

<EventRecordID>-1368025656</EventRecordID>

<Channel>Application</Channel>

<Computer>[redacted]</Computer>

<Security/>

</System>

<EventData>

<Data>Application '/LM/W3SVC/1365716517/ROOT' with physical root 'C:\home\site\wwwroot\' hit unexpected managed exception, exception code = '0xc0000005'. Please check the stderr logs for more information.</Data>

<Data>Process Id: 4236.</Data>

<Data>File Version: 13.1.22230.29. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: 21d42143378ad6cc4bcbaebfda5f3acddf13aa47</Data>

</EventData>

</Event>

<Event>

...

<EventData>

<Data>Application '/LM/W3SVC/1365716517/ROOT' with physical root 'C:\home\site\wwwroot\' failed to load coreclr. Exception message: CLR worker thread exited prematurely</Data>

<Data>Process Id: 4236.</Data>

<Data>File Version: 13.1.22230.29. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: 21d42143378ad6cc4bcbaebfda5f3acddf13aa47</Data>

</EventData>

</Event>

It seems CoreCLR was trying to load and failed with a native access violation exception (c0000005). Very odd. We did not get a dump of this but I wish we had.

Out-of-Process

When switching the app to run out-of-process, we encountered a different error. This is from the eventlog.xml:

<Event>

...

<EventData>

<Data>Application '/LM/W3SVC/1365716517/ROOT' with physical root 'C:\home\site\wwwroot\' failed to start process with commandline '"dotnet" .\[redacted].dll' with multiple retries. Failed to bind to port '31490'. First 30KB characters of captured stdout and stderr logs from multiple retries: </Data>

<Data>Process Id: 7032.</Data>

<Data>File Version: 13.1.22287.31. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: fbe05294ac5c88be848b4d57d60cb2657874da9b</Data>

</EventData>

</Event>

Nothing really useful there.

We enabled AspNetCoreModule's Enhanced Diagnostic Logging and saw that it was timing out while waiting for the app to report itself as started:

[aspnetcorev2_outofprocess.dll] Failed HRESULT returned: 0x8027025a at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\OutOfProcessRequestHandler\serverprocess.cpp:727

8027025a= E_APPLICATION_ACTIVATION_TIMED_OUT: The app didn't start in the required time.

We also enabled the stdout log via the web.config and found the app had started just fine:

dbug: Microsoft.Extensions.Hosting.Internal.Host[1]

Hosting starting

...

dbug: Microsoft.AspNetCore.Server.Kestrel[0]

No listening endpoints were configured. Binding to http://localhost:5000 by default.

info: Microsoft.Hosting.Lifetime[0]

Now listening on: http://localhost:5000

...

info: Microsoft.Hosting.Lifetime[0]

Application started. Press Ctrl+C to shut down.

info: Microsoft.Hosting.Lifetime[0]

Hosting environment: Test2

info: Microsoft.Hosting.Lifetime[0]

Content root path: C:\home\site\wwwroot

dbug: Microsoft.Extensions.Hosting.Internal.Host[2]

Hosting started

Turns out the app for some unknown reason was starting on the default localhost:5000. When hosting ASP.NET Core behind IIS and everything is working fine, AspNetCoreModule sets the ASPNETCORE_PORT environment variable to a dynamic port. Kestrel during startup is supposed to poll the value of that variable and use that port to listen on at 127.0.0.1. So in this case something was breaking down either on the environment variable side in ANCM or on the Kestrel side, or in between with the environment itself. Unfortunately we don't have more data to drill deeper into that because we were tinkering with the App Service based on an observation I made, and the problem appears to have been resolved.

Another Observation & Resolution

While perusing the ANCM Enhanced Diagnostic Logging I mentioned earlier, I came across this:

[aspnetcorev2.dll] Initializing logs for 'C:\home\SiteExtensions\AspNetCoreRuntime.3.1.x86\ancm\aspnetcorev2.dll'. Process Id: 7632.. File Version: 13.1.22287.31. Description: IIS ASP.NET Core Module V2. Commit: fbe05294ac5c88be848b4d57d60cb2657874da9b.

That struck me as odd because App Services itself provides all the .NET Core runtimes (including no-longer-supported ones like 3.1). So why was ANCM loading from a Site Extension?

In a new, test App Service with a basic ASP.NET Core 3.1 app deployed to it, this is what that log looks like:

[aspnetcorev2.dll] Initializing logs for 'C:\Program Files (x86)\IIS\Asp.Net Core Module\V2\aspnetcorev2.dll'. Process Id: 7496.. File Version: 13.1.19331.0. Description: IIS ASP.NET Core Module V2. Commit: 62eee6e6d21c95668a9e9529dce6562cc6c9f3bf.

That is where ANCM is normally located.

As a test on one of my own App Services, I installed the latest-available Site Extension for the .NET Core 3.1 runtime. I still had no issues, and I confirmed the ANCM log showed the location of ANCM had changed to the Site Extension one, same as the customer's.

I, personally, am not familiar with App Service Site Extensions and why the .NET Core runtime is available to use there when it's already built-in; however, it's just another copy of the runtime in a different location that theoretically shouldn't have issues. I will say, in this case the customer had an older version of the runtime installed via the Site Extension, while the latest available was 3.1.32 (the latest build).

On the call with the customer, as a test we removed the Site Extension completely, restarted the site, and confirmed ANCM was using the built-in version that comes with App Services. This immediately resolved the issues for both in-process and out-of-process setups.

Unfortunately, we likely won't be able to get more data on this problem and what was happening. I am thinking perhaps the fact that the Site Extension was out-of-date/an older version possibly had something to do with it. Thus, the takeaway here is if you have an app experiencing odd startup issues and if you have a Site Extension installed that contains the runtime for the app you are trying to run, try removing that Site Extension (or maybe update it if it needs to be updated?) and see if your issues go away. Make sure to stop and start the App Service as well, to make sure everything is fully picked-up.

Continue reading...