One of the things I love most about MVC3, and now ASP.NET Web API, is that pretty much any functionality or service that is used by your application, can be replaced with a custom one. One of these is the entire tracing mechanism that Web API uses.

Let’s have a look today at how you can build a simple System.Web.Http.Tracing.ITraceWriter implementation to provide support for a custom logging framework in your Web API - in our case it will be NLog.

More after the jump.

What is NLog? 🔗

Well, if you don’t know your are probably on a wrong blog 🙂 - but in short, NLog is a free open source logging framework for .NET (official site here), started by Microsoft’s Jarek Kowalski. It is extremely powerful, and very easy to setup. And it also happens to be my favorite one, that’s why I am going to use it here today.

With NLog you can easily write debug info to:

• files
• event log
• database
• network
• email
• command line console
• and many other providers

Why do we even need this and how to start? 🔗

A good question is why would you even need to do something? Wouldn’t using System.Diagnostics.Trace in your code enough?

Well, depends on how you look at it. In simple cases probably yes, but with plugging your own logging framework to ASP.NET Web API you get 2 major advantages:

• you can leverage on all the functionalities offered by NLog, like the above mentioned logging providers and easily log to different targets
• you channel all the internal ASP.NET Web API tracing to your provider as well. This means you can easily keep track of the traces that were put in by MSFT team and use those to debug/optimize your applications.

In order to plug your own trace provider to ASP.NET Web API you need a class that derives from System.Web.Http.Tracing.ITraceWriter.

public interface ITraceWriter  
{  
void Trace(HttpRequestMessage request, string category, TraceLevel level, Action<TraceRecord> traceAction);  
}  

In Web API RC the interface requires us to implement an additional method IsEnabled(). This is going to be obsolete in full release, as this method has been removed from the interface on May 15 in this commit. Therefore, since this code is written against RC, we will explicitly implement it but not use it for anything.

Our sample implementation 🔗

Let’s build a sample implementation. You can use any dummy Web API project for that - I just happen to have a redundant EF Code first/Ninject project, but that doesn’t really matter.

We need to start off by grabbing nLog from Nuget.

Next, we need to configure nLog in web.config. In the “configSections” add:

<section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog"/>

And directly under “configuration”, add:

<nlog xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">  
<targets>  
<target name="logfile" xsi:type="File" fileName="${basedir}/${date:format=yyyy-MM-dd}-webapi.log" />  
<target name="eventlog" xsi:type="EventLog" layout="${message}" log="Application" source="My Web API Application" />  
</targets>  
<rules>  
<logger name="*" minlevel="Trace" writeTo="logfile" />  
<logger name="*" minlevel="Trace" writeTo="eventlog" />  
</rules>  
</nlog>  

In this example we will use logging to a file and logging to event viewer, but obviously you are free to leverage on any of the powerful features of nLog. Note that I added ${basedir} in the file path - that is required to tell nLog that the file needs to be created under the web application’s root folder; otherwise it wouldn’t know where to put the file and no log file would be created.

We set the minimum log level to “Trace” - so that we are as verbose as possible, and log everything.

Now, we need a class implementing ITraceWriter:

public sealed class NLogger : ITraceWriter  
{  
private static readonly Logger classLogger = LogManager.GetCurrentClassLogger();

private static readonly Lazy<Dictionary<TraceLevel, Action<string>>> loggingMap =  
new Lazy<Dictionary<TraceLevel, Action<string>>>(() => new Dictionary<TraceLevel, Action<string>>  
{  
{TraceLevel.Info, classLogger.Info},  
{TraceLevel.Debug, classLogger.Debug},  
{TraceLevel.Error, classLogger.Error},  
{TraceLevel.Fatal, classLogger.Fatal},  
{TraceLevel.Warn, classLogger.Warn}  
});

private Dictionary<TraceLevel, Action<string>> Logger  
{  
get { return loggingMap.Value; }  
}

public void Trace(HttpRequestMessage request, string category, TraceLevel level, Action<TraceRecord> traceAction)  
{  
if (level != TraceLevel.Off)  
{  
var record = new TraceRecord(request, category, level);  
traceAction(record);  
Log(record);  
}  
}

private void Log(TraceRecord record)  
{  
//todo  
}  
}  

So, whenever the Trace() method would be invoked, we check if logging is on, build an instance of System.Web.Http.Tracing.TraceRecord, invoke a delegate (if passed) and call our private Log method, where we will introduce nLog logging.

The above mentioned delagates are used by internal Web API tracers from the System.Web.Http.Tracing.Tracers namespace. In our example we will use shorthand extensions from the static System.Web.Tracing.ITraceWriterExtensions, so we won’t explicitly pass any delegates to our ITraceWriter.

Notice that I also introduced a private Dictionary which will serve us as mapping between Web API’s System.Web.Http.Tracing.TraceLevel enum and nLog logging level methods.

Let’s look at the Log method:

private void Log(TraceRecord record)  
{  
var message = new StringBuilder();

if (record.Request != null)  
{  
if (record.Request.Method != null)  
message.Append(record.Request.Method);

if (record.Request.RequestUri != null)  
message.Append(" ").Append(record.Request.RequestUri);  
}

if (!string.IsNullOrWhiteSpace(record.Category))  
message.Append(" ").Append(record.Category);

if (!string.IsNullOrWhiteSpace(record.Operator))  
message.Append(" ").Append(record.Operator).Append(" ").Append(record.Operation);

if (!string.IsNullOrWhiteSpace(record.Message))  
message.Append(" ").Append(record.Message);

if (record.Exception != null && !string.IsNullOrWhiteSpace(record.Exception.GetBaseException().Message))  
message.Append(" ").Append(record.Exception.GetBaseException().Message);

Logger\[record.Level\](message.ToString());  
}  

This is a very simple method; depending on whether the “Operator” and “Exception” properties are set the message is more or less detailed. Then we invoke the appropriate nLog method to log the information.

Final step is to add our implmentation of ITraceWriter to GlobalConfigurarion. A side note - if you are using dependency injection, i.e. Ninject, and want to have logging available already there, you need to add the line below just at application start - and since DI frameworks usually use web activator, it would have to be somehwere under App_start folder.

GlobalConfiguration.Configuration.Services.Replace(typeof(ITraceWriter), new NLogger());  

Adding logging to our application 🔗

Now let’s add logging to several places in our application.

public class ValuesController : ApiController  
{  
private readonly IUrlRepository _repo;  
private readonly ITraceWriter _tracer;

public ValuesController(IUrlRepository repo)  
{  
_repo = repo;  
_tracer = GlobalConfiguration.Configuration.Services.GetTraceWriter();  
}

public IEnumerable<Url> Get()  
{  
var items = _repo.GetAll();  
_tracer.Info(Request, this.ControllerContext.ControllerDescriptor.ControllerType.FullName, "Info Loaded: " + items.Count());  
return items;  
}

public Url Get(int id)  
{  
var contact = _repo.Get(id);  
if (contact == null)  
{  
//not found  
_tracer.Warn(Request, this.ControllerContext.ControllerDescriptor.ControllerType.FullName, "Not found id: " + id);  
}

return contact;  
}

public int Post(Url url)  
{  
return _repo.Add(url);  
}

public Url Remove(int id)  
{  
var del = _repo.Delete(id);  
if (del == null)  
{  
//not found  
_tracer.Warn(Request, this.ControllerContext.ControllerDescriptor.ControllerType.FullName, "Cannot find id to delete: " + id);  
}  
return del;  
}

public bool Update(Url url)  
{  
if (this.ModelState.IsValid)  
{  
var result = _repo.Update(url);  
if (!result)  
_tracer.Error(Request, this.ControllerContext.ControllerDescriptor.ControllerType.FullName, "Cannot update Url model");

return result;  
}  
_tracer.Error(Request, this.ControllerContext.ControllerDescriptor.ControllerType.FullName, "Cannot update Url model");  
return false;  
}  
}  

We can add some elsewhere, i.e. in Ninject resolver and Global.asax:

public class NinjectResolver : NinjectScope, IDependencyResolver  
{  
private IKernel _kernel;  
public NinjectResolver(IKernel kernel)  
: base(kernel)  
{  
_kernel = kernel;  
//two dummy errors  
GlobalConfiguration.Configuration.Services.GetTraceWriter().Error(new HttpRequestMessage(), "urlzip.Infrastructure.NinjectResolver", "Error in Ninject resolver");  
GlobalConfiguration.Configuration.Services.GetTraceWriter().Fatal(new HttpRequestMessage(), "urlzip.Infrastructure.NinjectResolver", "Fatal in Ninject resolver"); }  
public IDependencyScope BeginScope()  
{  
return new NinjectScope(_kernel.BeginBlock());  
}  
}  

GlobalConfiguration.Configuration.Formatters.RemoveAt(1);  
GlobalConfiguration.Configuration.Services.GetTraceWriter().Debug(Request, "urlzip.WebApiApplication", "I'm in Global.asax and I just removed a formatter.");  

A note here - since the ITraceWriter requires an instance of HttpRequestMessage to be explicitly passed to the Trace method, we cheat a little, and pass an empty one in the places where it is not available (i.e. Global.asax).

Now let’s run the application, play around a little bit and see the log messages piling up. Since we set a very verbose trace level, you can see lots of helpful information coming from the internal Web API tracers.

The event viewer is also logging everything as it should:

One last thing worth mentioning, is that you can go even a step further, and instead of implementing a custom ITraceWriter you might implement an entirely own System.Web.Http.Tracing.ITraceManager. You’d then get the maximum control over anything that Web API does; however you’d have to effectively replace or rewrite everything that’s located under System.Web.Http.Tracing.Tracers - so all Web API’s internal tracers.

Summary 🔗

As most of the Web API stuff, plugging in your custom logging framework is very easy and smooth. With that in hand, you get very granular control over your tracing and debugging mechanisms and can leverage on the powerful features of your favorite logging framework - like I used nLog in this case.

Till next time!