Reading a FREB log, a Failed Request Tracing: IIS request processing pipeline execution

Brief: Once an HTTP request arrives at IIS, multiple modules participate along the pipeline stages to build a response. How do we know what the modules are doing and how long it takes? This is what we try to unveil here.

I’m not going to jump directly to inspecting a trace log, without first introducing some theory. Expect a rather long article, so here’s the table of content:

1. IIS does not respond to requests directly
2. The IIS request processing pipeline
3. Start working with Failed Request Tracing
4. Reading the tracing logs
5. A few about the modules
6. Example: Authentication and Authorization

       

 

 

Before reaching IIS…

 

We’re tempted to think that HTTP requests sent by clients are directly received by IIS. In fact, once a request arrives at the IP address of the IIS machine, the request is first treated by the kernel-level driver HTTP.SYS. If everything is fine, the request is signaled to a user-mode IIS worker process, w3wp.exe. Other processes may use HTTP.SYS too, but for the moment we talk IIS.

 

Requests from clients need to pass HTTP.SYS before reaching IIS

 

HTTP.SYS maintains a queue of requests for each of the application pool defined in IIS. In fact, simplified, an application pool means:

1. a queue of requests maintained by HTTP.SYS; and
2. settings for creating worker process(es), instance(s) of w3wp.exe, that would pick requests from that queue.

In HTTP.SYS, the queues of requests and their associated processes can be consulted with command-line:

netsh http show servicestate

So, an application pool has one HTTP.SYS requests queue and, generally, one w3wp.exe instance. The app pool process MAY load a .NET runtime, if configured, to execute one or more Asp.Net applications.

       

 

 

Inside IIS processing pipeline

 

HTTP.SYS ensures that the HTTP request is placed in the proper queue of an application pool. Now, the corresponding w3wp.exe instance can pick the request and start processing it to build a response. The w3wp.exe process is also loading modules, DLLs, with various functionality on processing the request. That includes the whatever Asp.Net application(s) should be executed by IIS.

The request enters a processing pipeline, with multiple stages. When the request reaches a stage, a notification is sent to modules that subscribed to that event. The modules are “invited” to perform operations on the request. A given module may or may not act, depending if it is enabled or not, or depending on its logic and configuration.

 

Request processing pipeline and participating modules inside a w3wp.exe worker process

 

For a given request, we have several modules acting along the pipeline. But there is only one handler per request; the handler is going to generate the response payload or body. Notice that we have a stage where the proper handler is determined for a given request.

Enabling Failed Request Tracing, it collects data about what the modules did on the request, and how long it took. It also shows details about the request, such as originating IP address and port, HTTP headers with cookies etc.

       

 

 

About Failed Request Tracing. Enabling

 

This feature is also known as FREB (Failed Request Event Buffering). The name is a bit misleading since we can collect a FREB log for successful requests too. Probably a name like Pipeline Execution Trace would be more appropriate.

To collect the FREB traces, 2 steps must be taken:

1. Define a rule or more, telling IIS in what conditions do we want a trace to be taken. IT could be for a specific page or any request, it could be for a specific response status code or for how long it took to serve the request. But simply having the rule(s) defined is not enough. We also must…
2. Enable the tracing. During the FREB trace collection, there is a small performance penalty. So, we should only have it enabled during data collection; after that, we should disable it. There is a limit on how many FREB logs can be taken, to avoid consuming too much disk space.

FREB can be enabled only at site level. But the rules can be defined on sub-applications or specific locations in the site, if we want to collect very targeted traces, for specific pages or URLs that we diagnose.

There are lots of articles on how to enable the IIS FREB tracing, so I’m going to only illustrate the basics:

 

The Tracing feature is not installed by default, you need to activate it first

  

Access the feature from any level to collect targeted traces. But only enable or disable from site level

  

Add rules: Under what conditions do we want a trace collected, and for what (kind of) requests

  

Enable from site level, customize location or maximum number of trace logs collected. Don’t forget to disable

       

 

 

Interpreting a FREB tracing log

 

The default location where FREB would save trace logs is C:\inetpub\logs\FailedReqLogFiles\W3SVCN\, where N is the ID of the IIS site that can found in IIS Manager by selecting the Sites node.

Trace logs are XML files; the accompanying XML transform - the freb.xsl file - helps “translating” XML into HTML.

Note on opening FREB logs for viewing:
AFAIK, when opening the XML files from the disk, only Internet Explorer side-loads the XSL to display the XML logs as a human friendly HTML pages. I frequently use the old FREB Viewer tool, which uses an IE control. If the FREB logs are accessed from a site instead of opening from disk, any browser would display the XML transformed into HTML with the help of the XSL; hence, you may create an http://localhost/FREBS test/viewing sub-app from where to access these logs with any browser.

 

The default Request Summary view of a FREB trace log

The basic view, Request Summary, displays the requested URL with verb and incoming port number, the HTTP response status code, the time it took to serve the request etc. If a non-success response is served, we can also see the module that set the respective response. Notice a couple of things:

• The Time Taken includes the network transfer time, not only the processing time inside IIS execution pipeline. It counts the time from the first request byte arriving to HTTP.SYS to the last byte of the response leaving HTTP.SYS. You might see a long time-taken for a PDF file, with actually just a few milliseconds processing time inside IIS; it is due to long network transfer time for a large file.
• The sub-status code (HttpSubStatus) is not part of the HTTP protocol specs. It is simply only logged by IIS to help troubleshooting. The reference for these codes may be found at https://linqto.me/http-response-codes. This sub-status code is normally not sent to the client, so you will not see it in a Fiddler trace, for example.

The full pipeline, Compact View, is where I jump. I get to see where the request is originating from, the request headers, cookies, the type of client, etc. The right-most column is useful when investigating performance issues.

 

Request headers and cookies are frequently relevant in troubleshooting

In the Compact View, I can see how pipeline stage notifications are sent to various modules, as in: ModuleName=”…” is receiving Notification=”…”.

It is common to see that many modules are simply notified, but they don’t actually act on the request; they might not be enabled or configured to do so. In such case, we see NOTIFY_MODULE_START immediately followed by NOTIFY_MODULE_END, for the same ModuleName.

 

Several modules do nothing on BEGIN_REQUEST. Then the Authentication stage begins, with modules “invited” to AUTHENTICATE_REQUEST

Modules will generally report something when they do act on the request. Look for what is happening in between NOTIFY_MODULE_START and NOTIFY_MODULE_END for the same module. For example, in the FREB below, we see that the WindowsAuthenticationModule successfully determines the user based on the Authorization request header that was sent by the client.

 

With Windows Integrated Authentication, the client sends an NTLM (alternatively Kerberos) ticket into an HTTP request header named Authorization…

  

…then the WindowsAuthenticationModule should be able to decipher the NTLM (or Kerberos) ticket to determine the request user

Sometimes, along the pipeline, we may see AspNetSomethingEnter and AspNetSomethingLeave: it’s a sign that a managed .NET module or handler is called to work on the request.

In the example below, the ManagedPipelineHandler is called to EXECUTE_REQUEST_HANDLER (remember that the handler should generate the response payload). But there is an error in the application, an exception. The Asp.Net framework is wrapping the exception in an error page, and sends that as a response, setting the response status code to 500 with sub-status 0. The “Internal Server Error” followed by “The operation completed successfully” sounds ironic, but in fact ManagedPipelineHandler does what it was designed to do: it does generate a response for the client, even if it’s not exactly what we expected.

 

Generally, a response with status 500.0 in the handler means an exception or error in the Asp.Net application being executed by w3wp.exe

 

Asp.Net wraps an exception in an error page – the much hated YSOD, Yellow Screen Of Death

With POST verb requests, we could even have access to what the client sent in the request payload, the body of the request. This may prove very useful in troubleshooting application’s errors, exceptions, or decisions.

 

Look for REQUEST_ENTITY and RESPONSE_ENTITY to get the payload, or body, sent by client or by server

       

 

 

More about modules

 

I think about modules as being DLLs loaded inside the w3wp.exe process. The code in a DLL may subscribe to stage notifications, acting like event handlers. The w3wp.exe may be configured to also load the .NET runtime; it would then be able to execute managed code built from C# or Visual Basic. So, we have native modules (those compiled for a specific machine architecture) or managed modules (running inside the .NET runtime, loaded from assembly DLLs). We have the modules that IIS ships with, or we can install separate optional modules, such as URL Rewrite or ARR, Application Request Routing, released by Microsoft or third parties. We could also develop our own modules and plug them into the IIS request processing pipeline.

IIS makes some native modules available to be added into the processing pipeline. For curious: consult applicationHost.config then <configuration> -> <system.webServer> -> <globalModules>.

Then sites or applications may be free to plug in or out modules used in the pipeline. The default list, which is inherited by all sites and applications, may be found consulting applicationHost.config then <configuration> -> <location path=””>.

A module usually acts on a single stage, meaning that it subscribes to only one stage notification. But we could have modules acting at 2 or more stages.

Some modules may signal that the request execution should end. For example, authentication or authorization modules may decide that the request cannot continue past their stage, because the request cannot be authenticated or authorized.

       

 

 

Authentication and authorization

 

Issues within the Authentication and Authorization pipeline stages are among the most common ones. These deserve some comments.

With IIS, if there are problems in the Authentication stage, they would generally result in 401.x responses, while problems in the Authorization would result in response status codes 403.x – remember the reference page https://linqto.me/http-response-codes.

You see, after the Authentication stage in the pipeline there MUST be a user determined for the HTTP request, even if that is the Anonymous one. At the end of Authentication, the User cannot be NULL. This is why Anonymous Authentication is used as a fallback: if we don’t have a user, we should at least set it to Anonymous, meaning that the UserName is an empty string:

 

An Anonymous (UserName=””) is set by IIS for a request by AnonymousAuthenticationModule

Failing to have a user set, after all subscribing modules were notified with AUTHENTICATE_REQUEST, “upsets” IIS. Not even Anonymous user? Then now we have a problem in the Authentication stage. Hence:

 

At the end of Authenticate we should not have User property of request being NULL

If after the Authentication we have the user being Anonymous, that may be fine from the IIS point of view. But it doesn’t necessarily mean that the request will be authorized. Further modules in pipeline may reject the request at the Authorize stage. Or maybe the application executing in the handler can refuse to serve the request because the user is unknown (anonymous). Or it may send a 302 response, to redirect the client to a login page.

When Windows Integrated Authentication is used, we disable Anonymous Authentication. If the user cannot be determined based on the Authorization request header, and we don’t have a fallback, then we would probably end up with a 401-Unauthorized response as above. But at least the WindowsAuthenticationModule would set a WWW-Authenticate=Negotiate header in the response, telling the client that a Kerberos or NTLM ticket is expected in the request, as Authorize header.

 

A normal Challenge Response: 401-Unauthorized response status code, with a WWW-Authenticate=Negotiate response header set

  

Happy troubleshooting, if I may say…