Entlib SLAB with MVC5 Website and Azure Trace Listener
If you’ve worked in .Net a while you will no doubt have come across the Microsoft Patterns and Practices Enterprise Libraries (Entlib) for Logging, Data Access, Exception handling etc, which are a set of application blocks to help us build applications with common components. Entlib SLAB (Semantic Logging Application Block) is a new logging block which helps us achieve logging in a more structured way rather than traditional logging libraries such as Entlib Logging and log4net. It allows us to use the .Net 4.5 EventSource class and log events to file, SQL database and Azure Storage tables.
I did research into SLAB in the preperation for the book I'm writing for Packt Publishing called "Learning Microsoft Azure" but didn't have space in the diagnostics chapter so I'm writing about it here.
It’s a good idea to do an extra bit of reading on SLAB as it’s quite complicated and we’re going to go through the implementation quite quickly here. There is some good information and examples on the CodePlex site: http://entlib.codeplex.com/wikipage?title=Entlib6CTPReleaseNotes.
We’ll implement Entlib SLAB in an MVC5 website, deployed to Azure with Azure table storage for our trace sink in the following procedure:
Install the EnterpriseLibrary.SemanticLogging.WindowsAzure NuGet package with the following command in the Package Manager Console:
Install-Package EnterpriseLibrary.SemanticLogging.WindowsAzure
Create an EventSource class for the website (I called mine CustomerWebsiteEvents and put it in a folder called Instrumentation). The EventSource class contains EventKeywords, EventTypes and EventOpcodes which are used to decorate explicit event methods for every operation you wish to log (sorry this is bit long-winded but everything is in there, I've taken the indents out to make it slightly easier to read too):
using System;
using System.Diagnostics.Tracing;
namespace AzureBakery.Sales.CustomerWebsite.Instrumentation
{
[EventSource(Name = "CustomerWebsiteEvents")]
public class CustomerWebsiteEvents : EventSource
{
public static class Keywords
{
public const EventKeywords Application = (EventKeywords)1L;
public const EventKeywords DataAccess = (EventKeywords)2L;
public const EventKeywords Controller = (EventKeywords)4L;
}
public static class Tasks
{
// For LogActionFilter
public const EventTask Action = (EventTask)1;
public const EventTask Result = (EventTask)2;
// General
public const EventTask Initialize = (EventTask)6;
public const EventTask GetProducts = (EventTask)7;
public const EventTask AddProductToOrder = (EventTask)8;
}
public static class Opcodes
{
public const EventOpcode Starting = (EventOpcode)20;
public const EventOpcode Started = (EventOpcode)21;
public const EventOpcode Error = (EventOpcode)22;
public const EventOpcode Ending = (EventOpcode)23;
public const EventOpcode Ended = (EventOpcode)23;
public const EventOpcode Executed = (EventOpcode)30;
public const EventOpcode Executing = (EventOpcode)31;
}
public static readonly CustomerWebsiteEvents Log = new CustomerWebsiteEvents();
[Event(100, Level = EventLevel.Verbose, Keywords = Keywords.Application, Task = Tasks.Initialize, Opcode = Opcodes.Starting, Version = 1)]
public void ApplicationStarting()
{
if (this.IsEnabled(EventLevel.Verbose, Keywords.Application))
{
this.WriteEvent(100);
}
}
[Event(101, Level = EventLevel.Informational, Keywords = Keywords.Application, Task = Tasks.Initialize, Opcode = Opcodes.Started, Version = 1)]
public void ApplicationStarted()
{
if (this.IsEnabled(EventLevel.Informational, Keywords.Application))
{
this.WriteEvent(101);
}
}
[Event(102, Level = EventLevel.Error, Keywords = Keywords.Application, Opcode = Opcodes.Error, Version = 1)]
public void ApplicationError(string exceptionMessage, string exceptionType)
{
if (this.IsEnabled(EventLevel.Error, Keywords.Application))
{
this.WriteEvent(102, exceptionMessage, exceptionType);
}
}
[Event(200, Level = EventLevel.Informational, Keywords = Keywords.Controller, Task = Tasks.Action, Opcode = Opcodes.Executing, Version = 1)]
public void ActionExecuting(string controller, string action)
{
if (this.IsEnabled(EventLevel.Informational, Keywords.Controller))
{
this.WriteEvent(200, controller, action);
}
}
[Event(201, Level = EventLevel.Verbose, Keywords = Keywords.Controller, Task = Tasks.Action, Opcode = Opcodes.Executed, Version = 1)]
public void ActionExecuted(string controller, string action)
{
if (this.IsEnabled(EventLevel.Verbose, Keywords.Controller))
{
this.WriteEvent(201, controller, action);
}
}
[Event(202, Level = EventLevel.Informational, Keywords = Keywords.Controller, Task = Tasks.Result, Opcode = Opcodes.Executing, Version = 1)]
public void ResultExecuting(string controller, string action)
{
if (this.IsEnabled(EventLevel.Informational, Keywords.Controller))
{
this.WriteEvent(202, controller, action);
}
}
[Event(203, Level = EventLevel.Verbose, Keywords = Keywords.Controller, Task = Tasks.Result, Opcode = Opcodes.Executed, Version = 1)]
public void ResultExecuted(string controller, string action)
{
if (this.IsEnabled(EventLevel.Verbose, Keywords.Controller))
{
this.WriteEvent(203, controller, action);
}
}
[Event(200, Level = EventLevel.Informational, Keywords = Keywords.Controller, Task = Tasks.GetProducts, Opcode = Opcodes.Started, Version = 1)]
public void ProductControllerGetProductsStarted()
{
if (this.IsEnabled(EventLevel.Informational, Keywords.Controller))
{
this.WriteEvent(200);
}
}
[Event(200, Level = EventLevel.Informational, Keywords = Keywords.Controller, Task = Tasks.GetProducts, Opcode = Opcodes.Ended, Version = 1)]
public void ProductControllerGetProductsEnded()
{
if (this.IsEnabled(EventLevel.Informational, Keywords.Controller))
{
this.WriteEvent(200);
}
}
[Event(200, Level = EventLevel.Error, Keywords = Keywords.Controller, Task = Tasks.GetProducts, Opcode = Opcodes.Error, Version = 1)]
public void ProductControllerGetProductsError(Exception ex)
{
if (this.IsEnabled(EventLevel.Error, Keywords.Controller))
{
this.WriteEvent(200, ex);
}
}
[Event(200, Level = EventLevel.Informational, Keywords = Keywords.Controller, Task = Tasks.AddProductToOrder, Opcode = Opcodes.Started, Version = 1)]
public void ProductControllerAddProductToOrderStarted()
{
if (this.IsEnabled(EventLevel.Informational, Keywords.Controller))
{
this.WriteEvent(200);
}
}
[Event(200, Level = EventLevel.Informational, Keywords = Keywords.Controller, Task = Tasks.AddProductToOrder, Opcode = Opcodes.Ended, Version = 1)]
public void ProductControllerAddProductToOrderEnded()
{
if (this.IsEnabled(EventLevel.Informational, Keywords.Controller))
{
this.WriteEvent(200);
}
}
[Event(200, Level = EventLevel.Error, Keywords = Keywords.Controller, Task = Tasks.AddProductToOrder, Opcode = Opcodes.Error, Version = 1)]
public void ProductControllerAddProductToOrderError(Exception ex)
{
if (this.IsEnabled(EventLevel.Error, Keywords.Controller))
{
this.WriteEvent(200, ex);
}
}
}
}
Next we need to modify the Global.asax to setup the listeners (the settings are from appSettings in web.config which we'll cover in a second), I've also added some tracing for the application start and a global errors:
public class MvcApplication : System.Web.HttpApplication
{
void Application_Start()
{
this.SetupListeners();
CustomerWebsiteEvents.Log.ApplicationStarting();
base.Error += MvcApplication_Error;
AreaRegistration.RegisterAllAreas();
FilterConfig.RegisterGlobalFilters(GlobalFilters.Filters);
RouteConfig.RegisterRoutes(RouteTable.Routes);
BundleConfig.RegisterBundles(BundleTable.Bundles);
CustomerWebsiteEvents.Log.ApplicationStarted();
}
private void SetupListeners()
{
// Get log details from web config (these can be configured in website CONFIGURE tab)
EventLevel logLevel = (EventLevel)Enum.Parse(typeof(EventLevel), ConfigurationManager.AppSettings["logLevel"]);
var logAccountName = ConfigurationManager.AppSettings["logAccountName"];
var logAccountKey = ConfigurationManager.AppSettings["logAccountKey"];
var logTableName = ConfigurationManager.AppSettings["logTableName"];
// Create listener and enable events
var listener = new ObservableEventListener();
listener.EnableEvents(CustomerWebsiteEvents.Log, logLevel, Keywords.All);
// Build storage connection string
var cnString = string.Format("DefaultEndpointsProtocol=https;AccountName={0};AccountKey={1}", logAccountName, logAccountKey);
// Log listener to azure listener.LogToWindowsAzureTable("WindowsAzureListener", cnString, logTableName);
}
void MvcApplication_Error(object sender, EventArgs e)
{
CustomerWebsiteEvents.Log.ApplicationError(Server.GetLastError());
}
}
As I mentioned, I've put all the table logging setting in the web config which can be modified in the portal if needed. Once we have a storage account, we can fill in the details:
<appSettings>
<add key="webpages:Version" value="3.0.0.0" />
<add key="webpages:Enabled" value="false" />
<add key="ClientValidationEnabled" value="true" />
<add key="UnobtrusiveJavaScriptEnabled" value="true" />
<!-- SLAB -->
<add key="logAccountName" value="myAccountName" />
<add key="logAccountKey" value="xxxxxxxxxxxxxxXXXXXXXXXXMyKey==" />
<add key="logTableName" value="SalesCustomerLog" />
<add key="logLevel" value="LogAlways" />
</appSettings>
Now, we can instrument our controllers and data access layer, here's an action from a controller:
[Authorize]
public ActionResult AddToOrder(int id)
{ CustomerWebsiteEvents.Log.ProductControllerAddProductToOrderStarted();
OrderItem item = null;
try
{
// Get customer details
var uid = User.Identity.GetUserId();
// Add to order
item = this._uow.AddToOrder(id, uid);
// Save
this._uow.SaveChanges();
}
catch (Exception ex)
{ CustomerWebsiteEvents.Log.ProductControllerAddProductToOrderError(ex);
throw;
}
CustomerWebsiteEvents.Log.ProductControllerAddProductToOrderEnded();
return RedirectToAction("Index", new { productType = item.Product.ProductType });
}
Now if we publish the website, then excecise it in the browser and examine the table storage, we should see our application tracing being logged:
Manually creating methods for numerous controller actions can be quite time consuming so I put together an ActionFilterAttribute to log the controller action life-cycle events:
public class LogActionFilter : ActionFilterAttribute
{
public override void OnActionExecuted(ActionExecutedContext filterContext)
{
var controllerName = filterContext.RouteData.Values["controller"].ToString();
var actionName = filterContext.RouteData.Values["action"].ToString();
CustomerWebsiteEvents.Log.ActionExecuted(controllerName, actionName);
base.OnActionExecuted(filterContext);
}
public override void OnActionExecuting(ActionExecutingContext filterContext)
{
var controllerName = filterContext.RouteData.Values["controller"].ToString();
var actionName = filterContext.RouteData.Values["action"].ToString();
CustomerWebsiteEvents.Log.ActionExecuting(controllerName, actionName);
base.OnActionExecuting(filterContext);
}
public override void OnResultExecuted(ResultExecutedContext filterContext)
{
var controllerName = filterContext.RouteData.Values["controller"].ToString();
var actionName = filterContext.RouteData.Values["action"].ToString();
CustomerWebsiteEvents.Log.ResultExecuted(controllerName, actionName);
base.OnResultExecuted(filterContext);
}
public override void OnResultExecuting(ResultExecutingContext filterContext)
{
var controllerName = filterContext.RouteData.Values["controller"].ToString();
var actionName = filterContext.RouteData.Values["action"].ToString();
CustomerWebsiteEvents.Log.ResultExecuting(controllerName, actionName);
base.OnResultExecuting(filterContext);
}
}
This can easily be added at controller level to achieve logging for all actions like this:
namespace AzureBakery.Sales.CustomerWebsite.Controllers
{
[LogActionFilter]
public class HomeController : Controller
{
public ActionResult Index()
{
return View();
}
Overall using EventSource and SLAB is extremely powerful for creating tailored tracing for websites compared with the standard System.Diagnostics.Trace object. We can create table logs which make it easy to pinpoint exactly the diagnostic information we're looking for by querying the EventId, Keyword, Type, OpCode and Level.