Logging for ASP.net CORE applications when you receive 502.3 and 500 status codes

As we start to see more and more ASP.net Core applications being used in production, our customers are coming to us with problems that are specific to these types of deployment scenarios. This article will attempt to deal with one such scenario – where the ASP.net Core web-application running behind IIS is sending back 502.3 response codes or simply 500 response codes.

IIS and ASP.net Architecture lesson.

Before we delve into the topic, a small architecture refresher is always nice to have. With ASP.net running on the full .Net framework, the .Net Runtime was hosted inside the IIS worker process, and all execution and response elaboration took place here. The diagram below attempts to show that:

1. The client computer (browser or application) will create and send an HTTP request to a web-server (which in our case is IIS)
2. The http.sys driver (kernel component of IIS) receives the request and queues for processing in the worker process (user mode component)
3. Once finished processing, the worker process has elaborated an HTTP response for the request, an sends it back to http.sys
4. sys sends the response back across the wire, to the requesting client.

Should you need a complete refresher of the IIS architecture, I would suggest the IIS architecture and components video series available here: http://linqto.me/n/IISArchitecture.

In the case of an ASP.net Core web-application that works behind an IIS web-server, the application runs in its own process, called dotnet.exe. This process is activated when the request is received by the worker process, and the dotnet.exe process is a child process of the w3wp.exe process. Let’s see the architecture:

With ASP.net Core request processing, the request follows the same path to the Worker process, so we will only focus on the different steps:

Step 3 – the ANCM (short for ASP.net Core Module) is a native module that lives inside the worker process, and will start the dotnet.exe process and then forward the request to it for processing.

Step 4 – the ASP.net Core application that lives inside dotnet.exe (child process of w3wp.exe) will process the request and issue a response.

This architecture should look pretty familiar to some since it resembles CGI (common gateway interface) execution for languages like Perl and Php in IIS, however the dotnet.exe process is not restarted after executing each request.

Causes of 502.3 responses for ASP.net Core applications

If we review the Http status and substatus codes for IIS (available here: http://linqto.me/IISCodes), the 502.3 status code translates into: Bad Gateway: Forwarder Connection Error. The gateway in this case is the IIS worker process, since this is working as a reverse proxy between the connecting client and the dotnet.exe process. In plain English, when you see this status code in the IIS logs, it means that the dotnet.exe process either did not respond to the request or took too long to respond (step 4 in the above diagram).

Using FREB tracing, in such cases does not yield many more details. You will only see that the status code of the request is changed by the ANCM module but will not have any information as to what occurred in the dotnet.exe process, which can be a challenge.

The first thing you need to know is that the ANCM module does expose configuration in IIS. While not available under an Icon in the central pane of the IIS Manager, this configuration can be reached by using the configuration manager feature in the IIS manager, and then going into the system.WebServer/AspNetCore tag as shown below:

Settings available for the ANCM :

Some settings to call out here are the following:

• Start-up time limit: the allowed limit for the dotnet.exe process to start and begin processing requests. The default value is 120 seconds.
• Shutdown time limit: when the worker process shuts down for recycling, it will have to await the shutdown of the dotnet.exe process before it performs a shutdown of its own. This time is by default 10 seconds.
• Request timeout: the amount of time that the ANCM is willing to wait for the dotnet.exe process to process an HTTP request it has been forwarded. Should this time be exceeded, the ANCM module will return a 502.3 response code.

How to gather more data – logging

The ANCM module also provides the possibility to turn on logging for the ASP.net Core application. This can be done by setting the value of stdoutLogEnaled to ‘true’. The tricky part is that the Logs folder (default value of the stdoutLogFile) has to be created by hand, if not, no logs will be generated. As such, you will need to bring up File Explorer, navigate to the root folder for your ASP.net Core website (such as C:\inetpub\wwwroot) and create a folder called ‘Logs’ inside.

You can also control the level of verbosity for the logs. This is done inside the appsettings.json file in which you have the following configuration section:

"Console": {
      "LogLevel": {
        "Default": "Warning"
      }
    }

By default, the level is set to ‘Warning’ and all first-hand exceptions and critical errors will be logged. If you set the logging level to ‘Information’ everything, including the request Urls will be logged. Below is an excerpt from one such log show that a new request has arrived for processing:

info: Microsoft.AspNetCore.Hosting.Internal.WebHost[1]
      Request starting HTTP/1.1 OPTIONS http://corewebapi/api/EchoCors 

You can see, you have information on the Request verb used, the url and protocol version.

When trying to understand why your application is not behaving as expected, using logging to review errors in execution in this way can provide you with vital clues for troubleshooting. In the ASP.net Core WebAPI CORS tutorial I have written on this blog, this technique proved invaluable for debugging the WebAPI application while writing the tutorial.

Written by: Paul Cociuba

Reviewed by: Muna AlHasan