This is the second part of the Logging series. For your convenience you can find other parts in the table of contents in Part 1 – Correlations

We have our loggers and correlators, now we need to use them. Since we want to create them with each request, we can use action filters to automate the job. Let’s start with WebAPI2.

Important

Before we start: it is crucial to register loggers and correlators properly in DI container. They need to be registered in request lifetime scope so all services injected to the controllers get the same instance of the correlator and logger. If we mess this thing our logs will be useless.

REST API

Let’s see the code:

using System.Linq;
using System.Net.Http;
using System.Web.Http.Controllers;
using System.Web.Http.Filters;
using DomainCommons.Correlations;
using DomainCommons.Loggers;
using ActionFilterAttribute = System.Web.Http.Filters.ActionFilterAttribute;

namespace AzureCommons.Filters
{
	public class WebApiCorrelationActionFilterAttribute : ActionFilterAttribute
	{
		public override void OnActionExecuting(HttpActionContext actionContext)
		{
			SetActivity(actionContext);

			var logger = GetFromContainer<ILogger>(actionContext.Request);
			logger.Log(LogLevel.Information, $"Executing with parameters: {string.Join(", ", actionContext.ActionArguments.Select(p => $"{p.Key} = {p.Value}"))}.");
		}

		private static void SetActivity(HttpActionContext actionContext)
		{
			var actionDescriptor = actionContext.ActionDescriptor;
			string actionName = actionDescriptor.ActionName;
			string controllerName = actionDescriptor.ControllerDescriptor.ControllerType.FullName;

			var correlator = GetFromContainer<ICorrelator>(actionContext.Request);
			correlator.Activity = $"{controllerName}.{actionName}";
		}

		public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
		{
			var logger = GetFromContainer<ILogger>(actionExecutedContext.Request);
			logger.Log(LogLevel.Information, "Execution finished");

			var correlator = GetFromContainer<ICorrelator>(actionExecutedContext.Request);
			actionExecutedContext.Response?.Headers?.Add(Constants.CorrelationCounterHeader, correlator.GetLogicalTime().ToString());
			actionExecutedContext.Response?.Headers?.Add(Constants.CorrelationIdHeader, correlator.GetCorrelationId());
		}

		private static T GetFromContainer<T>(HttpRequestMessage request)
		{
			// This is much easier then registering dependencies via reflection to have constructor injection.
			var requestScope = request.GetDependencyScope();
			var dependency = (T)requestScope.GetService(typeof(T));
			return dependency;
		}
	}
}

This is pretty obvious. On entering action I generate the activity and log parameters. When action is finished I log this fact and add correlation headers to the response.

One thing related to the DI. I am using Autofac and I could register this action filter in DI and filter provider. However, it is easier to just create action filter as an attribute, register it globally, and get dependencies from WebAPI’s services resolver. Of course this is up to you.

Web job

WebAPI was easy, web job is even easier. I am using Autofac as well in this part of the system but I have no web request here. This is why I create dependent scope and register logger and correlator as instances:

private static void RunInScope(TextWriter log, string activity, Action<ILifetimeScope> action)
{
	var correlator = new MemoryBasedCorrelator
	{
		Activity = activity
	};

	var logger = new WebJobLogger(log, 
		"JobHandlers",
		correlator
	);

	using (var scope = AutofacConfig.Container.BeginLifetimeScope(b =>
	{
		b.RegisterInstance<ILogger>(logger).SingleInstance();
		b.RegisterInstance<ICorrelator>(correlator).SingleInstance();
	}))
	{
		try
		{
			logger.Log(LogLevel.Information, $"{activity} - starting");
			action(scope);
		}
		catch (Exception e)
		{
			logger.Log(LogLevel.Error, $"{activity} - exception: {e}");
		}
		finally
		{
			logger.Log(LogLevel.Information, $"{activity} - done");
		}
	}
}

Next, all my actions need to extract dependencies from the scope:

public static void DoSomething([TimerTrigger("01:00:00", RunOnStartup = true)] TimerInfo timer, TextWriter log)
{
	RunInScope(log, "Some action", scope =>
	{
		var service = scope.Resolve<IService>();
		Task.Run(async () => await service.DoJob()).Wait();
	});
}

This way all your services should get correct instance of logger and correlator, and logs should go to the TextWriter given by the Azure.

Of course you could use Azure’s JobHost services resolver.

Sitefinity

Now the case of Sitefinity. Actually, there are four cases to consider.

WebForms

First case is WebForms part of the CMS. When you open the page with widgets, you actually start with the WebForms infrastructure which then internally creates another requests to your Feather widgets written as MVC. This WebForms path needs to be handled but I don’t use DI for this. I simply create logger manually and run the code since I don’t have much of my code handled in WebForms:

using System;
using System.Web;
using AzureCommons.Correlations;
using AzureCommons.Loggers;
using DomainCommons.Loggers;

namespace AzureCommons.Filters
{
	public static class WebFormsCorrelationRequestHandler
	{
		public static void BeginRequest(object sender, EventArgs e)
		{
			var correlator = new RequestHeadersCorrelator();
			var logger = new WebAppLogger("CMS WebForms", correlator);
			HttpContext.Current.Items[Constants.LoggerItem] = logger;

			logger.Log(LogLevel.Information, $"Beginning request from {sender}: {e}");
		}

		public static void EndRequest(object sender, EventArgs e)
		{
			var logger = (ILogger)HttpContext.Current?.Items[Constants.LoggerItem];

			if (logger == null)
			{
				return;
			}

			logger.Log(LogLevel.Information, $"Ending request from {sender}: {e}");

			if (HttpContext.Current?.Response?.Headers == null)
			{
				return;
			}

			if (HttpContext.Current.Response.HeadersWritten)
			{
				return;
			}

			HttpContext.Current.Response.Headers[Constants.CorrelationIdHeader] = logger.Correlator.GetCorrelationId();
			HttpContext.Current.Response.Headers[Constants.CorrelationCounterHeader] = logger.Correlator.GetLogicalTime().ToString();
		}
	}
}

On start I create the logger and store it globally in request items so I can extract it when the request is finished. Other stuff should be obvious.

I need to run these methods on each request but this is easy, simply handle events in Global.asax.cs.

Sitefinity’s loggers

We already know how to override Sitefinity’s loggers. Since they are not tied to the request (Sitefinity runs internal jobs), they should have separate logger with different name, so we can distinguish them. But this is easy, simply create a logger when overriding trace listeners.

MVC widgets

Last piece of Sitefinity is MVC path for running widgets. We know how to inject services using DI container so now we only need to create an action filter:

using System.Linq;
using System.Web.Mvc;
using DomainCommons.Correlations;
using DomainCommons.Loggers;

namespace AzureCommons.Filters
{
	public class MvcCorrelationActionFilter : IActionFilter
	{
		private readonly ILogger _logger;
		private readonly ICorrelator _correlator;

		public MvcCorrelationActionFilter(ILogger logger, ICorrelator correlator)
		{
			_logger = logger;
			_correlator = correlator;
		}

		public void OnActionExecuting(ActionExecutingContext filterContext)
		{
			SetActivity(filterContext);

			_logger.Log(LogLevel.Information, $"Executing with parameters: {string.Join(", ", filterContext.ActionParameters.Select(p => $"{p.Key} = {p.Value}"))}.");

		}

		private void SetActivity(ActionExecutingContext filterContext)
		{
			var actionDescriptor = filterContext.ActionDescriptor;
			string actionName = actionDescriptor.ActionName;
			string controllerName = actionDescriptor.ControllerDescriptor.ControllerType.FullName;

			_correlator.Activity = $"{controllerName}.{actionName}";
		}

		public void OnActionExecuted(ActionExecutedContext filterContext)
		{
			_logger.Log(LogLevel.Information, "Execution finished");

			
			if (filterContext.HttpContext?.Response?.HeadersWritten == true)
			{
				return;
			}

			filterContext.HttpContext?.Response?.AddHeader(Constants.CorrelationIdHeader, _correlator.GetCorrelationId());
			filterContext.HttpContext?.Response?.AddHeader(Constants.CorrelationCounterHeader, _correlator.GetLogicalTime().ToString());
		}
	}
}

We need to register this filter so we need a filter provider:

using System.Collections.Generic;
using System.Web.Mvc;
using Ninject;

namespace Cms
{
	public class GlobalFilterProvider : IFilterProvider
	{
		private readonly IKernel _dependencyResolver;

		// We get IKernel instead of IDependencyResolver because apparently Sitefinity doesn't use MVC providers
		public GlobalFilterProvider(IKernel dependencyResolver)
		{
			_dependencyResolver = dependencyResolver;
		}

		public IEnumerable<Filter> GetFilters(ControllerContext controllerContext, ActionDescriptor actionDescriptor)
		{
			foreach (var filter in _dependencyResolver.GetAll<IActionFilter>())
			{
				yield return new Filter(filter, FilterScope.Global, null);
			}
			foreach (var filter in _dependencyResolver.GetAll<IAuthorizationFilter>())
			{
				yield return new Filter(filter, FilterScope.Global, null);
			}
			foreach (var filter in _dependencyResolver.GetAll<IExceptionFilter>())
			{
				yield return new Filter(filter, FilterScope.Global, null);
			}
			foreach (var filter in _dependencyResolver.GetAll<IResultFilter>())
			{
				yield return new Filter(filter, FilterScope.Global, null);
			}
			foreach (var filter in _dependencyResolver.GetAll<System.Web.Mvc.Filters.IAuthenticationFilter>())
			{
				yield return new Filter(filter, FilterScope.Global, null);
			}
		}
	}
}

And now we need to register the filter in DI container and we are done:

dependencyResolver.Bind<ICorrelator>().To<RequestHeadersCorrelator>().InSitefinityRequestScope();
dependencyResolver.Bind<ILogger>().ToMethod(c => new WebAppLogger("CMS", c.Kernel.Get<ICorrelator>())).InSitefinityRequestScope();
dependencyResolver.Bind<IActionFilter>().To<MvcCorrelationActionFilter>().InSitefinityRequestScope();

We need one more thing: scope for MVC request:

public static class IKernelExtensions
{
	public static IBindingNamedWithOrOnSyntax<T> InSitefinityRequestScope<T>(this IBindingInSyntax<T> syntax)
	{
		return syntax.InScope(context => HttpContext.Current);
	}
}

Unity

There is another place where you should consider registering your logger and correlator: Unity in Sitefinity. For instance, you could log stuff in users provider.

Summary

Great! We have our loggers and correlators injected in all places. In the next part we will handle exceptions and errors using another filters.