ASP.NET Core 2.2 returning 500.30 on Azure App Service: a debugging story

Last Friday I spent some time investigating an annoying bug we had in production: we have a relatively standard Single Page Web Application, in which a ASP.NET Core 2.2 Web API serves a React.js front-end. The Web API is runs on Azure App Service, using the InProcess hosting mode.

The issue: from time to time, the API would hang and start raising an HTTP 500.30 status code on any endpoint.

When that happened, either a restart or the proactive auto-healing of Azure App Service would eventually fix the issue and restore the functionality. However, this obviously wasn’t something we could live with, so I started doing some digging to understand it a bit further.

It was quite an interesting journey, especially because I was able to investigate the bug without any changes in the code, so I thought it could’ve been useful if I shared it.

What does a 500.30 mean?

Just to be clear and set the context, it’s probably best to clarify that a 500.30 isn’t your average 500 error :) it’s not caused by a controller throwing an exception during the execution, it means something more profound: the unhandled exception is happening during the boot of the application, which therefore is not starting at all.

So my first idea was to have a look at the code in Program.cs:

As you can see, when configuring the WebHostBuilder , we are doing some interesting stuff to read some secrets stored in KeyVault:

• first of all, we acquire an Authentication Token from Azure Active Directory using the Managed Service Identity of the application;
• next, we use this to add a ConfigurationProvider, which will be responsible of feeding the Configuration of the application by reading the data from KeyVault.

This approach is a best practice, recommended in the official documentation of Azure KeyVault. Anyway, it’s worth noting that it adds a dependency from a couple of external components to your startup logic, and should they fail, your application will not be able to start.

It’s a good beginning, but not enough, since IIS would retry to start the application multiple times, and in normal conditions it would eventually succeed. I needed to dig further…

A look at Azure App Service Diagnostics

Since this error was happening during the application startup, it’s needless to say that nothing was being logged in Application Insights, so the next place to go was the “Diagnose and Solve problems” blade in App Service, where I was prompted with the following report:

This didn’t give me much more information, aside from confirming my findings that the ASP.NET Core module itself was failing and — interesting but expected — that loading data from KeyVault was slowing down the application startup a bit.

Time to head to the App Service Logs blade and turn on some diagnostic logs to know a bit more about this issue, and then opening Kudu:

Logs to the rescue

At this point I was fairly sure that there was something wrong with the interaction with KeyVault, but I still wasn’t sure what exactly wasn’t functioning as expected. There are several logs that start being captured the moment you activate the options in the image above, but among them the most interesting one is definitely eventlog.xml, stored in the /LogFiles folder.

Here I could occasionally find some entries like the following:

<Event>
  <System>
    ...
  </System>
  <EventData>
    <Data>Application '/LM/W3SVC/1673357803/ROOT' with physical root 'D:\home\site\wwwroot\' hit unexpected managed exception, exception code = '0xe0434352'. Please check the stderr logs for more information.</Data>
    ...
  </EventData>
</Event>

Unfortunately this was another generic error, not really helpful to understand what was going on.

Note: This is one aspect in which ASP.NET Core 2.2 differs from 3.x: as you can easily verify, when an exception happens, ASP.NET Core 3.0 automatically dumps the first few lines of stderr into the EventLog, whereas ASP.NET Core 2.2 only leaves the generic message above.

In order to read the stderr logs in Azure App Service, you want to setup the stdout redirection by modifying the web.config file:

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <system.webServer>
    <handlers>
      <add name="aspNetCore" ... />
    </handlers>
    <aspNetCore processPath="dotnet" arguments="..."
      stdoutLogEnabled="true"
      stdoutLogFile="\\?\%home%\LogFiles\stdout"
      hostingModel="InProcess" />
  </system.webServer>
</configuration>

After saving the file, IIS will start storing the stdout content into text files:

You can configure the severity level at which you want your logs to be captured, by either modifying the appconfig.json file directly, or just by setting an environment variable. However — and I do think this is a bug of 2.2— if the error happens during the startup phase and the app is hosted InProcess, all you find is an empty file, like the one highlighted in the picture.

Note: this is another behavior which has been fixed in ASP.NET Core 3.x, where you would see the log being properly captured.

Therefore, in order to see some meaningful info, I needed to switch to the OutOfProcess hosting model, by modifying the web.config file again:

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <system.webServer>
    <handlers>
      <add name="aspNetCore" ... />
    </handlers>
    <aspNetCore processPath="dotnet" arguments="..."
      stdoutLogEnabled="true"
      stdoutLogFile="\\?\%home%\LogFiles\stdout"
      hostingModel="OutOfProcess" />
  </system.webServer>
</configuration>

As soon as I did it, the details of the exception were finally revealed:

The root cause

Now, *that* was definitely interesting and unexpected. We had configured the networking security policies in KeyVault to only allow connections either from a specific VNET or from “trusted Microsoft services”:

However, for some reasons, sometimes the Azure Web App is not recognized as a Trusted Microsoft Service and gets blocked, as you can clearly see from the exception we’ve managed to trace.

I’m not sure why this ultimately happens, however after reading the documentation, I’ve realized that trusting App Service in KeyVault is only supported when deploying TLS certificates. In other words, we were operating in an unsupported scenario.

Was that the cause of this issue (which again, was happening inconsistently)? I don’t honestly know, but the fix was to explicitly whitelist all the possible outbound IPs of the App Service to cater for when the trusted services policy would not kick off as expected.

Conclusions

During this article we’ve described a journey to investigate a transient issue in production, which was preventing an ASP.NET Core 2.2 application to successfully start up.

Diagnosing this kind of errors in Azure App Service requires some knowledge about the underlying infrastructure, since the PaaS nature of the service doesn’t provide you full control over the environment.

However, by doing a qualitative analysis of the code in the first place, and then looking at the logs captured in the stderr, we were able to identify the root issue: it was a call to Azure KeyVault occasionally being rejected by the firewall.

I’m not sure if this was happening because it’s an unsupported scenario or because it’s an issue on the internals of Azure. However, explicitly whitelisting the outbound IP addresses of the App Service did the trick in fixing the problem.