ASP.NET Web API (available for download or on CodePlex) supports tracing of both framework and application code. This post describes the fundamentals of Web API tracing, how to trace from your code, and how to make your code or framework code trace to your favorite logger.

Overview

Tracing in this context means a notification mechanism that allows framework and application code to say things like “Object X is now performing operation Y” or “Object X encountered exception Z when performing operation Y.”

Tracing in Web API is done via the ITraceWriter interface described below. Both framework and application code can trace through ITraceWriter, allowing framework and user traces to be written to the same destination and to be correlated against the same Http request.

Each trace notification is captured in a TraceRecord instance created by the ITraceWriter implementation. Code asking to trace is responsible for filling in the details of that TraceRecord.

Every trace notification must specify the Http request, a category (string) and a trace level (enum).

The Http request is required so that all traces can correlate to the single request that caused that code to run.

The category is an arbitrary string that has meaning to the developer or to the framework. A typical trace category is “System.Web.Http.ModelBinding.” The category has no particular meaning to the WebApi product – it is merely captured in the TraceRecord. We’ll see below how ITraceWriter implementations can make decisions based on this category.

The trace level is one of the TraceLevel enum values. It also has no particular meaning to the WebApi product, but may have meaning to the ITraceWriter implementation. Like category, this value is simply captured in the TraceRecord.

All attempts to trace are conditional, subject to the ITraceWriter implementation. For example, code may say “I want to trace some information at level Info, category ‘MyCategory’”. The ITraceWriter implementation may decide that level and/or category are not currently enabled, and that trace attempt will be ignored.

What is available “in the box”

The Web API framework exposes the public ITraceWriter interface and an internal tracing layer I’ll talk about shortly.

However, Web API does not provide any ITraceWriter implementations in the box. Our intent is that the user community will develop ITraceWriter implementations that bridge to other products, such as ETW, System.Diagnostics, NLog, Log4Net, Elmah, etc.

How to enable tracing in your app

Tracing is off by default in Web API. To enable it, you must register some ITraceWriter implementation as a service. The presence of an ITraceWriter service is what activates WebApi framework code to trace to it..

In a self-hosted environment, registering a trace writer would look like this:

        1: HttpSelfHostConfiguration config = new HttpSelfHostConfiguration(myUri);

       2: config.Services.Replace(typeof(ITraceWriter), new MyTraceWriter());

       3: HttpServer server = new HttpSelfHostServer(config);

In a web-hosted environment, it would look like this (in Global.asax.cs):

       1: protected void Application_Start()

       2: {    

       3:     HttpConfiguration config = GlobalConfiguration.Configuration;

       4:     config.Services.Replace(typeof(ITraceWriter), new MyTraceWriter());

       5: }

Creating an ITraceWriter implementation

The ITraceWriter interface

The only public API a trace writer must implement is ITraceWriter.

       1: public interface ITraceWriter

       2: {    

       3:     void Trace(HttpRequestMessage request, 

       4:                string category,

       5:                TraceLevel level, 

       6:                Action<TraceRecord> traceAction);

       7: }

The ITraceWriter contract

The ITraceWriter API has only a single method Trace(). Its parameters are:

request – the HttpRequestMessage with which to associate the trace information.
category – a user defined string specifying the category to associate with this trace. The WebApi framework uses category names that match its namespaces, but developers can use whatever category names make sense to them. Using a dotted name (“MyApplication.DataModel.Management”) generally integrates best with existing logging tools.
level – an enumeration specifying the severity level of the trace (see below).
traceAction – an Action callback that accepts a TraceRecord (see below). This action is provided by the caller and will be invoked only when the trace writer implementation decides it is configured to capture traces at the specified category and level.

The decision when to call traceAction for more details is entirely up to the trace writer implementation. Existing logging mechanisms generally support category hierarchies and may choose to match some prefix of the given category. Also they may to filter the severity level, such as all traces at level Warn and above. WebApi does not provide any way to configure trace writers regarding their current category or level.

The Trace() method is responsible to do these things:

Determine whether tracing is enabled for the given category and level..
If not enabled, return immediately without calling the caller’s traceAction
If enabled:

- Allocate a new TraceRecord (which may be a derived type for that trace writer)

- Invoke the caller’s traceAction, passing the new TraceRecord to allow the caller to fill in the details

- Do something with that completed TraceRecord

The reason the Trace() method looks the way it does is to address the following problems inherent in tracing:

Performance -- beginning trace users are often tempted to fetch resources eagerly and to format strings before discovering their trace will be ignored. This is a guaranteed performance killer. The Trace() method uses a callback pattern to encourage the user code to evaluate its trace information lazily only when it will be used.
Exception protection – the code asking to trace may encounter an exception creating its information. For example, it might use a String.Format() with an incorrect number of parameters. Few applications think to protect all their traces with try/catch or to unit test all their tracing statements, effectively leaving latent fatal exceptions in their app. The Trace() pattern allows the ITraceWriter implementation to use its own try/catch to protect the application and to report a problem in the user’s tracing code as it chooses.
Creation and lifespan of TraceRecord – some tracing products ask callers to create the equivalent of a TraceRecord before calling the tracing layer. That has 2 problems – it means the record class itself cannot be subclassed, and the lifespan of that record is ambiguous. What happens if I change a field in that record after I ask to trace it? Am I required to dispose it? Because the Trace() method is responsible for creating the TraceRecord, we achieve these benefits:

- The trace writer can avoid creating a TraceRecord unless it knows it will use it.

- The trace writer can avoid calling the user’s traceAction unless it knows it will use its information

- The trace writer can create derived TraceRecord types that contain additional implementation-specific information.

- The caller sees the TraceRecord only inside its traceAction callback and is therefore discouraged from holding onto it.

- The disposal of the TraceRecord, if required by the trace writer, is under the trace writer’s control.

The TraceLevel enumeration

All traces are associated with a severity level. The interpretation of what these levels mean is entirely up to the trace writer implementation. WebApi does not interpret them in any way. This enumeration maps to values commonly used by diagnostic and logging tools, and the values are ordered the way these tools generally use them (example: “if (level >= TraceLevel.Warn)…”).

       1: public enum TraceLevel

       2: {

       3:     Off = 0,

       4:     Debug = 1,

       5:     Info = 2,

       6:     Warn = 3,

       7:     Error = 4,

       8:     Fatal = 5

       9: }

The WebApi product code currently traces normal activity at Info level. Situations that may cause a downstream failure, such as a model binding error, trace at the Warn level. All exceptions caught by the product tracing code traces at the Error level.

A simple ITraceWriter implementation

Here is possibly the world’s simplest ITraceWriter implementation that writes to the console. Even though it is simple, it demonstrates how a trace writer should behave. In this case, the contract is to write every trace request to the console.

       1: class SimpleConsoleTraceWriter : ITraceWriter

       2: {

       3:     public void Trace(HttpRequestMessage request, string category, 

       4:                       TraceLevel level, Action<TraceRecord> traceAction)

       5:     {

       6:         TraceRecord traceRecord = new TraceRecord(request, category, level);

       7:         traceAction(traceRecord);

       8:         ShowTrace(traceRecord);

       9:     }

  

    private void ShowTrace(TraceRecord traceRecord)

    {

        Console.WriteLine(

            String.Format(

                "{0} {1}: Category={2}, Level={3} {4} {5} {6} {7}",

                traceRecord.Request.Method.ToString(), 

                traceRecord.Request.RequestUri.ToString(), 

                traceRecord.Category,

                traceRecord.Level,

                traceRecord.Kind,

                traceRecord.Operator,

                traceRecord.Operation,

                traceRecord.Exception != null

                    ? traceRecord.Exception.GetBaseException().Message

                    : !string.IsNullOrEmpty(traceRecord.Message)

                        ? traceRecord.Message

                        : string.Empty

            ));

    }

}

Adding this SimpleConsoleTraceWriter to HttpConfiguration.Services will cause all user and framework traces to be displayed on the console. I’ve found that even as simple a trace writer as this is valuable in understanding the Web API framework itself. It reveals the execution flow through the framework, including error paths. This kind of tracer is also useful for debugging your application, because you see exactly where in the execution flow things go awry.

Here is a sample of what this trace writer displays for a single request:

What information gets traced

The unit of tracing is the TraceRecord created by the ITraceWriter.Trace() method.

Some of the properties are pre-initialized by the constructor, but when ITraceWriter.Trace() calls the caller’s traceAction the caller is responsible for filling in all the other properties it wishes to trace. It is permitted to leave some properties not set, and trace writer implementations must tolerate this.

Here is the current definition of TraceRecord:

public class TraceRecord

{

    public TraceRecord(HttpRequestMessage request, 

                       string category, TraceLevel level)

    {

        Timestamp = DateTime.UtcNow;

        Request = request;

        RequestId = request != null ? request.GetCorrelationId() : Guid.Empty;

        Category = category;

        Level = level;

    }

  

    public string Category { get; set; }

    public Exception Exception { get; set; }

    public TraceKind Kind { get; set; }

    public TraceLevel Level { get; set; }

    public string Message { get; set; }

    public string Operation { get; set; }

    public string Operator { get; set; }

    public Dictionary<object, object> Properties {get; }

    public HttpRequestMessage Request { get; private set; }

    public Guid RequestId { get; private set; }

    public HttpStatusCode Status { get; set; }

    public DateTime Timestamp { get; private set; }

}

What the framework traces

The framework traces most of the main services registered in the HttpConfiguration.Services. It also traces the execution flow of objects returned from any of these services’ methods. For example, the registered IContentNegotiator is traced. And if its Negotiate method returns a MediaTypeFormatter, then that formatter’s methods will also be traced. You can see that in action in the console output above.

The framework tracing code always traces both a Begin and an End trace (TraceKind.Begin and TraceKind.End) bracketing the start and finish of each operation. In the example above, there is a Begin trace for DefaultContentNegotiator.Negotiate(), showing when the framework entered that code. And there is also an End trace showing when DefaultContentNegotiator.Negotiate(), completed, either successfully or not. If completion is unsuccessful, the exception associated with failure is written into the TraceRecord.

The framework code traces the public and protected entry points of each service, regardless whether that service is a default provided by Web API or is user code that replaced the default service. In this way, user code replacing a default service will also be traced. The user does not need to add extra tracing logic to make that happen. The framework traces only the public and protected entry points visible to it through the API of that service at compile time. It is unable to trace additional public or protected methods on user-defined types.

How to trace from user code

This piece of code demonstrates how a trace is done at the lowest level, namely interacting directly with the ITraceWriter API:

ITraceWriter writer = Configuration.Services.GetTraceWriter();

if (writer != null)

    writer.Trace(

        Request, "MyCategory", TraceLevel.Debug,

        (traceRecord) => 

        { traceRecord.Message = 

            String.Format("Inside MyMethod with param = {0}", value); } );

Notice that the ITraceWriter is retrieved from the list of services in the configuration. It might be null if none was registered.

If it is not null, the caller asks to trace with an HttpRequestMessage, a category, and a trace level.

Possibly the most important point to observe here is that the caller also passes in an Action<TraceRecord> delegate. This action will be called by the ITraceWriter if and only if it requires more information. The code performing the trace is required to fill-in the given TraceRecord with whatever it wants traced. In this example, the tracing code only wanted to add a message. If the category or level are not being currently being traced by the ITraceWriter implementation, that Action delegate will not be called.

Both framework code and user code trace the same way.

Friendlier trace methods

The example above looks complicated because it represents the lowest level interaction possible with ITraceWriter.

But to make things easier, there are many friendlier extension methods for ITraceWriter. For example, this code would do exactly the same thing as the code above:

ITraceWriter writer = Configuration.Services.GetTraceWriter();

if (writer != null)

    writer.Debug(Request, "MyCategory",

                 "Inside MyMethod with param = {0}", value);

The friendlier methods hide the details of the Action callback, but they evaluate the other parameters only if tracing is really enabled. In this case, the invisible String.Format() would execute only if tracing was enabled for that category and level.

The full list of extension methods will be shown by Intellisense for ITraceWriter.

Tracing to an existing logging product

ITraceWriter is just an abstraction layer that can be used as a bridge to other 3rd party products. The most common scenario will probably be a logging product.

For example, if you like using NLog in your applications, you would build or obtain an NLog-specific ITraceWriter.

We expect the user community to develop industrial-strength ITraceWriter implementations for popular logging products, but I'll contribute more samples in future posts.

By using a custom ITraceWriter that writes to a logging product like this, both your application code and Web API framework code will send their traces to it..

Controlling what is traced

Determining which categories and levels are currently enabled is the responsibility of the ITraceWriter implementation. The Web API framework has no concept of trace configuration or determining which categories and levels are enabled.

The intent of this approach is to rely on the ITraceWriter implementation’s own mechanisms to configure what gets traced and where.

For example, if you use an NLog-specific ITraceWriter, you should configure tracing through NLog configuration mechanisms.

Analyzing what is traced

This also is the responsibility of the ITraceWriter implementation. The Web API framework has no concept of storing traces or analyzing them,

To use the example above, if you are using an NLog-specific ITraceWriter, the trace “store” is configurable, and it will be done using NLog’s configuration options.

To analyze what is traced, you use whatever tools you normally use to analyze that store.

Tracing to ITraceWriter versus writing directly to the logging product

So suppose you have an NLog ITraceWriter that allows framework and user code to trace to NLog. Should you continue to log directly to NLog or should you call ITraceWriter.Trace()?

That is your choice, and both approaches will work. But here are some considerations when making that choice:

Writing directly to your logger:

Advantages:

- Your app may already do this

- You can use special features of your logger during tracing

Disadvantages:

- Your app is tightly coupled to that logger implementation

- Your traces will not be correlated to their specific Http request unless you do it explicitly

- A hard dependency on a specific logger may make it difficult to integrate with community code or to contribute to it

Writing to your logger through ITraceWriter:

Advantages:

- Your app is not tightly coupled to any logger implementation.

- Everything traced by your code or the framework is correlated to the same Http request

- Using or contributing to community code will be easier with this abstraction layer

Disadvantages:

- You might need to convert app code already writing to that logger

- The TraceRecord might not be able to contain everything you want logged

Other uses of ITraceWriter

ITraceWriter is just an abstraction layer. Though the most common use will be to bridge to some logging product, it can be used for different purposes.

Here are some I’ve considered or tried:

Quick and dirty performance monitoring – because the framework traces both Begin and End for each operation, an analysis tool can measure average execution times of every framework or user operation. A performance trace writer could expose its own ApiController allowing some dashboard UI to watch performance dynamically.
An error reporting tool – an ITraceWriter could be written to send an email whenever a Fatal trace record was written or to integrate with existing error reporting mechanisms.
Quick and dirty analytics – an ITraceWriter could capture basic usage information, such as which endpoints are being used, average response time, the frequency of errors, etc. Again, it could expose its own ApiController to allow some dashboard to monitor that.
Just-in-time tracing – you could write a “rolling” trace writer that wraps another ITraceWriter. It could keep a small rolling buffer of traces but not forward them to the inner trace writer until some event occurred, such as an Error trace. In this way, you could run for days without capturing a single trace, but when that special error occurs, your inner trace writer could record the traces immediately before and after the error, This can be useful tracking down stress issues or hard-to-reproduce scenarios.
A learning/debugging tool – even a simple console ITraceWriter can be useful when learning the Web API execution sequence or in debugging an app (e.g. “Why is my action’s parameter not properly model bound?” or “Why am I getting back Json instead of my custom media type?” or “When is an exception filter called?”)
Testing – spy or mock ITraceWriter test doubles can be useful to assert your trace statements are correct or to inject faults or delays into the running app, An ITraceWriter that unconditionally invokes the Action<TraceRecord> callback is also a great way to flush out any buggy trace statements that throw.

Tracing to multiple trace writers

As you can see by the examples, tracing code expects only a single ITraceWriter in HttpConfiguration.Services. But what if you want more than one?

Consider this scenario:

The developers write application code that traces to ITraceWriter
At deployment time, the team decides they want framework and application traces to go a persistent store they can view remotely.
The team also decides they want errors to be reported to Elmah
The test team decides to use ITraceWriter to inject faults and delays when the app is used in a test environment

The easiest way to approach this is to create a single aggregating ITraceWriter that discovers the presence of these multiple writers and delegates the IsEnabled() and Trace() calls to them.

Web API does not provide an aggregating ITraceWriter, but writing one should not be difficult.

How framework tracing works behind the scenes

I mentioned above that the Web API framework will trace to whatever ITraceWriter is found in HttpConfiguration.Services. What I didn’t mention was the slightly unusual approach we took to implement this. When no ITraceWriter is found, no tracing occurs from the framework for this simple reason -- the core Web API framework contains no code aware of tracing!

Most framework implementations I have seen sprinkle tracing statements throughout their code. These are usually bracketed with “are you enabled?” tests to avoid a performance penalty. I think of this as the “trace from the inside out” approach. It’s fairly straight forward but suffers these drawbacks:

It might not trace what the developer wants to see
Any user-written extensions must also remember to trace or there is no record of their execution
There is almost always at least some overhead even when tracing is disabled
Such framework code is often tightly coupled to a specific tracing framework
It may not be possible for user code to write to that tracing framework
It is usually not possible to redirect the framework traces to an alternate tracing framework

Web API took a different approach that I call “trace from the outside in.” It works this way: if Web API determines during startup that an ITraceWriter is registered, it wraps a trace-aware object around services registered in the HttpConfiguration.Services and then replaces the original service with this trace-aware wrapper.

These trace-aware wrappers override the public and protected entry points of their respective wrapped service so that they can trace the Begin, then invoke the wrapped service, and then trace the End. They also wrap a try/catch around the wrapped-object’s method to trace error paths.

This approach has these benefits:

If you don’t want tracing, you don’t pay for it
All framework services trace using the same Begin/End pattern
User-written code replacing framework code will trace automatically
The user can redirect where framework code traces
This approach establishes that the primary extensibility points in Web API are factored into small enough polymorphic chunks that they can be overridden and observed.

The framework tracing code is internal, so you cannot override it to change the way it traces. However you can replace the entire tracing layer altogether by replacing the ITraceManager in the HttpConfiguration.Services. But that is a subject for another post.

Conclusions

This post was an overview of how tracing works in Web API, and I hope you have a sense of how to use it to trace from your code and to capture what the framework is tracing.

In future posts I’ll explore some ITraceWriter implementations and offer some samples.

roncain

Tracing in ASP.NET Web API