Web API Tracing with SLAB and Elasticsearch

The article demonstrates how to use Web API Tracing, and trace the data using SLAB, in-process or out-of-process to a flat file or an Elasticsearch sink. Semantic.Logging from Enterprise Library now includes an Elasticsearch sink. The NuGet package also includes an implementation of the IExceptionLogger interface and a logging ActionFilter which logs the data using SLAB.

Update: Version 1.0.6 now supports Web API 2.2

Code: https://github.com/WebApiContrib/WebApiContrib.Tracing.Slab
NuGet Package: http://www.nuget.org/packages/WebApiContrib.Tracing.Slab/

Using the NuGet package for Web API Slab Tracing

Example in src code (github): WebApiContrib.Tracing.Slab.DemoApp

Download the latest version of WebApiContrib.Tracing.Slab from NuGet

When the package is installed, it also installs the packages which it depends on. Now the tracing needs to be enabled. This can be done at App_Start/WebApiConfig. The following code needs to be added to the global Web API config:

config.EnableSystemDiagnosticsTracing();
config.Services.Replace(typeof(ITraceWriter), new SlabTraceWriter());

This enables tracing for Web API and sets the custom SlabTraceWriter as the ITraceWriter.

If you’re using SLAB OUT-OF-PROCESS logging, the application is ready. Now configure the SemanticLogging-svc.xml. Underneath are examples for 2 sinks, an Elasticsearch sink and also a webapitracing.log flat file sink.

<?xml version="1.0" encoding="utf-8" ?>
<configuration xmlns="http://schemas.microsoft.com/practices/2013/entlib/semanticlogging/etw"
               xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
               xsi:schemaLocation="http://schemas.microsoft.com/practices/2013/entlib/semanticlogging/etw SemanticLogging-svc.xsd">
  <traceEventService/>
  <sinks>

    <elasticsearchSink instanceName="damienbod" connectionString="http://localhost:9200" name="out" index="outofprocessslab" type="webapitracing">
      <sources>
        <eventSource name="WebApiTracing" level="LogAlways"/>
      </sources>
    </elasticsearchSink>

    <flatFileSink name="svcRuntime" fileName="webapitracing.log" >
      <sources>
        <eventSource name="WebApiTracing" level="LogAlways"/>
      </sources>
      <eventTextFormatter header="----------"/>
    </flatFileSink>

  </sinks>
</configuration>

And here’s the results in Elasticsearch:

If you’re logging in-process, add the following to your Global.asax.

// Only to test in-proc logging
var listener = new ObservableEventListener();
listener.EnableEvents(WebApiTracing.Log, EventLevel.LogAlways, Keywords.All);
listener.LogToFlatFile("test.log");

This adds a flat file listener for the WebApiTracing events.

NOTE: NuGet package EnterpriseLibrary.SemanticLogging.TextFile is required for this.
Results in file log:

----------
EventId : 303, Level : Informational, Message : TraceLevel.Info  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Web.Http.Controllers ValuesController ExecuteAsync, Payload : [message :  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Web.Http.Controllers ValuesController ExecuteAsync] , EventName : InformationalInfo, Timestamp : 2014-04-10T17:44:10.6702662Z

----------
EventId : 303, Level : Informational, Message : TraceLevel.Info  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Web.Http.Request Content-type='application/json; charset=utf-8', content-length=unknown, Payload : [message :  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Web.Http.Request Content-type='application/json; charset=utf-8', content-length=unknown] , EventName : InformationalInfo, Timestamp : 2014-04-10T17:44:10.6702754Z

----------
EventId : 303, Level : Informational, Message : TraceLevel.Info  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Net.Http.Formatting JsonMediaTypeFormatter WriteToStreamAsync Value='value', type='String', content-type='application/json; charset=utf-8', Payload : [message :  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Net.Http.Formatting JsonMediaTypeFormatter WriteToStreamAsync Value='value', type='String', content-type='application/json; charset=utf-8'] , EventName : InformationalInfo, Timestamp : 2014-04-10T17:44:10.6703001Z

----------
EventId : 303, Level : Informational, Message : TraceLevel.Info  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Net.Http.Formatting JsonMediaTypeFormatter WriteToStreamAsync, Payload : [message :  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Net.Http.Formatting JsonMediaTypeFormatter WriteToStreamAsync] , EventName : InformationalInfo, Timestamp : 2014-04-10T17:44:10.6703321Z

----------
EventId : 303, Level : Informational, Message : TraceLevel.Info  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Web.Http.Controllers ValuesController Dispose, Payload : [message :  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Web.Http.Controllers ValuesController Dispose] , EventName : InformationalInfo, Timestamp : 2014-04-10T17:44:10.6703804Z

----------
EventId : 303, Level : Informational, Message : TraceLevel.Info  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Web.Http.Controllers ValuesController Dispose, Payload : [message :  GET http://localhost:63107/api/Values/32679 Host: localhost:63107
User-Agent: Fiddler
 System.Web.Http.Controllers ValuesController Dispose] , EventName : InformationalInfo, Timestamp : 2014-04-10T17:44:10.6703842Z

Limitations:

At present, the Event IDs are fixed from 301 to 306 for the default EventSource.

private const int TraceLevelFatal = 301;
private const int TraceLevelError = 302;
private const int TraceLevelInformational = 303;
private const int TraceLevelLogAlways = 304;
private const int TraceLevelVerbose = 305;
private const int TraceLevelWarning = 306;

If you want to use your own EventSource, then use the following code in the Web API config:

// Example using an example EventSource
var exectueLogDict = new Dictionary<TraceLevel, Action<string>>();
WebApiTracingWithSignalRExample.RegisterLogger(exectueLogDict);
config.EnableSystemDiagnosticsTracing();
config.Services.Replace(typeof(ITraceWriter), new SlabTraceWriter(exectueLogDict));

The EventSource requires a RegisterLogger method. This method maps trace levels to your Events.

 public static void RegisterLogger(Dictionary<TraceLevel, Action<string>> exectueLogDict)
 {
   exectueLogDict.Add(TraceLevel.Info, Log.Informational);
   exectueLogDict.Add(TraceLevel.Debug, Log.Verbose);
   exectueLogDict.Add(TraceLevel.Error, Log.Error);
   exectueLogDict.Add(TraceLevel.Fatal, Log.Critical);
   exectueLogDict.Add(TraceLevel.Warn, Log.Warning);
 }

Example of External Trace with SignalR diagnosis: WebApiContrib.Tracing.Slab.DemoApp.WithSignalR

Nuget Package src code (github): WebApiContrib.Tracing.Slab

This assembly contains 2 classes, one which implements the ITraceWriter from Web API and the EventSource. The SlabTraceWriter class maps the TraceLevel of the trace to an Action in the EventSource in the RegisterLogger method. When Web API sends a trace, the trace information is added to the message and logged.

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

namespace WebApiContrib.Tracing.Slab
{
    public class SlabTraceWriter : ITraceWriter
    {
        private readonly Dictionary<TraceLevel, Action<string>> _exectueLogDict;

        public SlabTraceWriter()
        {
            _exectueLogDict = new Dictionary<TraceLevel, Action<string>>();
            WebApiTracing.RegisterLogger(_exectueLogDict);
        }

        /// <summary>
        /// An event src can be used from your project if you require special EventId etc...
        /// </summary>
        /// <param name="exectueLogDict"></param>
        public SlabTraceWriter(Dictionary<TraceLevel, Action<string>> exectueLogDict)
        {
            _exectueLogDict = exectueLogDict;
        }

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

            var record = new TraceRecord(request, category, level);
            traceAction(record);
            LogToSlab(record);
        }

        private void LogToSlab(TraceRecord record)
        {
            var message = new StringBuilder();
            AddRequestDataToMessage(record, message);
            AddRecordDataToMessage(record, message);

            var result = message.ToString();
            _exectueLogDict[record.Level].Invoke(result);
        }

        private void AddRecordDataToMessage(TraceRecord record, StringBuilder message)
        {
            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.IsNullOrEmpty(record.Exception.GetBaseException().Message))
                message.Append(" ").AppendLine(record.Exception.GetBaseException().Message);
        }

        private void AddRequestDataToMessage(TraceRecord record, StringBuilder message)
        {
            if (record.Request != null)
            {
                if (record.Request.Method != null)
                {
                    message.Append(" ").Append(record.Request.Method.Method);
                }

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

                message.Append(" ").Append(record.Request.Headers);
            }
        }
    }
}

The EventSource class is used to log to the ETW. The Events are mapped to different trace levels.

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

namespace WebApiContrib.Tracing.Slab
{
    [EventSource(Name = "WebApiTracing")]
    public class WebApiTracing : EventSource
    {
        private const int TraceLevelFatal = 301;
        private const int TraceLevelError = 302;
        private const int TraceLevelInformational = 303;
        private const int TraceLevelLogAlways = 304;
        private const int TraceLevelVerbose = 305;
        private const int TraceLevelWarning = 306;

        public static void RegisterLogger(Dictionary<TraceLevel, Action<string>> exectueLogDict)
        {
            exectueLogDict.Add(TraceLevel.Info, Log.Informational);
            exectueLogDict.Add(TraceLevel.Debug, Log.Verbose);
            exectueLogDict.Add(TraceLevel.Error, Log.Error);
            exectueLogDict.Add(TraceLevel.Fatal, Log.Critical);
            exectueLogDict.Add(TraceLevel.Warn, Log.Warning);
        }

        public static readonly WebApiTracing Log = new WebApiTracing();

        [Event(TraceLevelFatal, Message = "TraceLevel.Fatal{0}", Level = EventLevel.Critical)]
        public void Critical(string message)
        {
            if (IsEnabled()) WriteEvent(TraceLevelFatal, message);
        }

        [Event(TraceLevelError, Message = "TraceLevel.Error{0}", Level = EventLevel.Error)]
        public void Error(string message)
        {
            if (IsEnabled()) WriteEvent(TraceLevelError, message);
        }

        [Event(TraceLevelInformational, Message = "TraceLevel.Info{0}", Level = EventLevel.Informational)]
        public void Informational(string message)
        {
            if (IsEnabled()) WriteEvent(TraceLevelInformational, message);
        }

        [Event(TraceLevelLogAlways, Message = "WebApiTracing LogAlways{0}", Level = EventLevel.LogAlways)]
        public void LogAlways(string message)
        {
            if (IsEnabled()) WriteEvent(TraceLevelLogAlways, message);
        }

        [Event(TraceLevelVerbose, Message = "TraceLevel.Debug{0}", Level = EventLevel.Verbose)]
        public void Verbose(string message)
        {
            if (IsEnabled()) WriteEvent(TraceLevelVerbose, message);
        }

        [Event(TraceLevelWarning, Message = "TraceLevel.Warn{0}", Level = EventLevel.Warning)]
        public void Warning(string message)
        {
            if (IsEnabled()) WriteEvent(TraceLevelWarning, message);
        }
    }
}

See this link for Elasticsearch Sematic.logging

See this link for Slab OUT-OF-PROCESS logging

You can also log all unhandled Web API exceptions by add the following to your Web.Api config method:

// Do this if you want to log all unhandled exceptions
config.Services.Add(typeof(IExceptionLogger), new SlabLoggingExceptionLogger());

An ActionFilter is also available for logging request and response messages with slab. Here’s an example:

    // Here you can log a resquest/response  messages.
    [SlabLoggingFilterAttribute]
    public class ValuesController : ApiController
    {
        // GET api/values
        public IEnumerable<string> Get()
        {
            return

TODO:

1. Provide a Self-Hosted example
2. Sign the assembly if required

Links:

https://github.com/WebApiContrib

http://www.strathweb.com/2014/03/per-request-tracing-asp-net-web-api/

http://www.asp.net/web-api/overview/testing-and-debugging/tracing-in-aspnet-web-api

Tags: Elasticsearch, Semantic Logging, SLAB, TopHeaderMenu, Tracing