Language

Tracing in ASP.NET Web API

By |

When you are trying to debug a web-based application, there is no substitute for a good set of trace logs. This tutorial shows how to enable tracing in ASP.NET Web API. You can use this feature to trace what the Web API framework does before and after it invokes your controller. You can also use it to trace your own code.

ASP.NET Web API is designed so that you can use your choice of tracing/logging library, whether that is ETW, NLog, log4net, or simply System.Diagnostics.Trace.

To collect traces, implement the ITraceWriter interface. Here is a simple example:

public class SimpleTracer : ITraceWriter
{
    public void Trace(HttpRequestMessage request, string category, TraceLevel level, 
        Action<TraceRecord> traceAction)
    {
        TraceRecord rec = new TraceRecord(request, category, level);
        traceAction(rec);
        WriteTrace(rec);
    }

    protected void WriteTrace(TraceRecord rec)
    {
        var message = string.Format("{0};{1};{2}", 
            rec.Operator, rec.Operation, rec.Message);
        System.Diagnostics.Trace.WriteLine(message, rec.Category);
    }
}

The ITraceWriter.Trace method creates a trace. The caller specifies a category and trace level. The category can be any user-defined string. Your implementation of Trace should do the following:

  1. Create a new TraceRecord. Initialize it with the request, category, and trace level, as shown. These values are provided by the caller.
  2. Invoke the traceAction delegate. Inside this delegate, the caller is expected to fill in the rest of the TraceRecord.
  3. Write the TraceRecord, using any logging technique that you like. The example shown here simply calls into System.Diagnostics.Trace.

Setting the Trace Writer

To enable tracing, you must configure Web API to use your ITraceWriter implementation. You do this through the HttpConfiguration object, as shown in the following code:

public static void Register(HttpConfiguration config)
{
    config.Services.Replace(typeof(ITraceWriter), new SimpleTracer());
}

If you are hosting in ASP.NET, do this inside the Application_Start method, defined in Global.asax. (See Configuring ASP.NET Web API.)

Only one trace writer can be active. By default, Web API sets a "no-op" tracer that does nothing. Call HttpConfiguration.Services.Replace to replace this default tracer with your own. (The "no-op" tracer exists so that tracing code does not have to check whether the trace writer is null before writing a trace.)

Adding Traces to Your Code

Adding a trace writer gives you immediate access to the traces created by the Web API pipeline. You can also use the trace writer to trace your own code:

using System.Web.Http.Tracing;

public class ProductsController : ApiController
{
    public HttpResponseMessage GetAllProducts()
    {
        Configuration.Services.GetTraceWriter().Info(
            Request, "ProductsController", "Get the list of products.");

        // ...
    }
}

Get the trace writer by calling HttpConfiguration.Services.GetTraceWriter. From a controller, this method is accessible through the ApiController.Configuration property.

To write a trace, you can call the ITraceWriter.Trace method directly, but the ITraceWriterExtensions class defines some extension methods that are more friendly. For example, the Info method creates a trace with trace level Info.

Performance Tracing

The Web API pipeline writes traces at the beginning and end of an operation. The TraceRecord class includes a TimeStamp property, so you can use this information to see how long various operations take.

Traces written at the start of an operation have the Kind property set to TraceKind.Begin, and traces at the end of an operation have Kind set to TraceKind.End. To get the total execution time, match Begin and End traces. The following code shows a trace writer that collects traces and matches them when GetPerformanceRecords is called. You could even write an API controller that returns the performance data from this trace writer.

using System;
using System.Collections.Generic;
using System.Net.Http;
using System.Web.Http.Tracing;

public class PerfRecord
{
    public Guid RequestId { get; set; }
    public double Msec { get; set; }
    public string Category { get; set; }
    public string Operation { get; set; }
}

public class PerfTracer : ITraceWriter
{
    List<TraceRecord> begin = new List<TraceRecord>();
    List<TraceRecord> end = new List<TraceRecord>();

    public void Trace(HttpRequestMessage request, string category, TraceLevel level,
        Action<TraceRecord> traceAction)
    {
        TraceRecord rec = new TraceRecord(request, category, level);
        traceAction(rec);
        WriteTrace(rec);
    }

    // Collect traces in memory.
    protected void WriteTrace(TraceRecord rec)
    {
        switch (rec.Kind)
        {
            case TraceKind.Begin:
                begin.Add(rec);
                break;

            case TraceKind.End:
                end.Add(rec);
                break;
        }
    }

    // Match "begin" and "end" traces and calculate the timing.
    public IEnumerable<PerfRecord> GetPerformanceRecords()
    {
        var records = new List<PerfRecord>();
        foreach (var rec in begin)
        {
            var index = end.FindIndex((r) =>
                (rec.RequestId == r.RequestId && rec.Category == r.Category &&
                    rec.Operation == r.Operation && rec.Operator == r.Operator));
            if (index != -1)
            {
                var match = end[index];
                records.Add(new PerfRecord()
                {
                    Msec = (match.Timestamp - rec.Timestamp).TotalMilliseconds,
                    Operation = rec.Operation,
                    Category = rec.Category,
                    RequestId = rec.RequestId
                });
                end.RemoveAt(index);
            }
        }
        begin.Clear();
        end.Clear();
        return records;
    }
}

How Web API Tracing Works

Tracing in Web API uses a in Web API uses a facade pattern: When tracing is enabled, Web API wraps various parts of the request pipeline with classes that perform trace calls.

For example, when selecting a controller, the pipeline uses the IHttpControllerSelector interface. With tracing enabled, the pipleline inserts a class that implements IHttpControllerSelector but callls through to the real implementation:

Web API tracing uses the facade pattern.

The benefits of this design include:

  • If you do not add a trace writer, the tracing components are not instantiated and have no performance impact.
  • If you replace default services such as IHttpControllerSelector with your own custom implementation, tracing is not affected, because tracing is done by the wrapper object.

You can also replace the entire Web API trace framework with your own custom framework, by replacing the default ITraceManager service:

config.Services.Replace(typeof(ITraceManager), new MyTraceManager());

Implement ITraceManager::Initialize to initialize your tracing system. Be aware that this replaces the entire trace framework, including all of the tracing code that is built into Web API.

Mike Wasson

By Mike Wasson, Mike Wasson is a programmer-writer at Microsoft.

Table of Contents

Getting Started with ASP.NET Web API

Creating Web APIs

Web API Clients

Web API Routing and Actions

Working with HTTP

Formats and Model Binding

OData Support in ASP.NET Web API

Security

Hosting ASP.NET Web API

Testing and Debugging

Extensibility

Resources