In this recipe, we take a look at how to handle cross cutting concerns in our Nancy application. Specifically, we will see the following:
Use the before and after hooks to log every incoming request and to log all the status codes of all responses
Use the error hook to log all unhandled exception from our modules
Both of these are achieved via the application wide hooks; that is, they work for all requests. There are similar module specific hooks; for example, they work only on requests handled by that module.
We will use the NLog (http://nlog-project.org) logging library in this recipe but this could be any logging library.
We will work on the code done so far. So open up your copy of the code from the previous recipe, or get a copy of it from the code download.
The following steps help you understand how to hook into Nancy's request pipeline:
Install the NLog NuGet package to both the
TodoNancyandTodoNancyTestsprojects.Add a new C# file to the
TodoNancyTestsproject and call itRequestLoggingTests.cs.Add tests that check if requests, status codes, and exceptions are logged. We achieve this by overriding the NLog configuration such that all log messages are written to an object in memory. This enables us to assert that the log entries we expect have been written. The test code you need looks as follows:
public class RequestLoggingTests { private Browser sut; private MemoryTarget actualLog; private const string infoRequestlogger = "|INFO|RequestLogger"; private const string errorRequestlogger = "|ERROR|RequestLogger"; public RequestLoggingTests() { sut = new Browser(new Bootstrapper()); OverrideNLogConfiguration(); } private void OverrideNLogConfiguration() { actualLog = new MemoryTarget(); actualLog.Layout += "|${exception}"; SimpleConfigurator.ConfigureForTargetLogging(actualLog, LogLevel.Info); } [Theory] [InlineData("/")] [InlineData("/todos/")] [InlineData("/shouldnotbefound/")] public void ShouldLogIncomingRequests(string path) { sut.Get(path); Assert.True(TryFindExptedInfoLog(actualLog, "Handling request GET \"" + path + "\"")); } [Theory] [InlineData("/", HttpStatusCode.OK)] [InlineData("/todos/", HttpStatusCode.OK)] [InlineData("/shouldnotbefound/", HttpStatusCode.NotFound)] public void ShouldLogStatusCodeOffResponses(string path, HttpStatusCode expectedStatusCode) { sut.Get(path); Assert.True(TryFindExptedInfoLog(actualLog, "Responding " + expectedStatusCode +" to GET \"" + path + "\"")); } [Fact] public void ShouldLogErrorOnFailingRequest() { try { sut.Delete("/todos/illegal_item_id"); } catch {} finally { Assert.True(TryFindExptedErrorLog(actualLog, "Input string was not in a correct format.")); } } private static bool TryFindExptedInfoLog(MemoryTarget actualLog, string expected) { return TryFindExptedLogAtExpectedLevel(actualLog, expected, infoRequestlogger); } private static bool TryFindExptedErrorLog(MemoryTarget actualLog, string expected) { return TryFindExptedLogAtExpectedLevel(actualLog, expected, errorRequestlogger); } private static bool TryFindExptedLogAtExpectedLevel(MemoryTarget actualLog, string expected, string requestloggerLevel) { var tryFindExptedLog = actualLog.Logs .Where(s => s.Contains(requestloggerLevel)) .FirstOrDefault(s => s.Contains(expected)); if (tryFindExptedLog != null) return true; Console.WriteLine("\"{0}\" not found in log filtered by \"{1}\":", expected, requestloggerLevel); Console.WriteLine(actualLog.Logs.Aggregate("[\n\t{0}\n]", (acc, s1) => string.Format(acc, s1 + "\n\t{0}"))); return false; } }To make these tests pass, we need to hook into Nancy before each request, after each request, and on errors. We do this in the bootstrapper by adding handlers to the
Before,After, andOnErrorpipelines. We also go a little bit ahead and add NLog configuration, even though we do not have tests for it, by adding the following code to our bootstrapper:private Logger log = LogManager.GetLogger("RequestLogger"); protected override void ApplicationStartup(TinyIoCContainer container, IPipelines pipelines) { base.ApplicationStartup(container, pipelines); SimpleConfigurator.ConfigureForTargetLogging(new AsyncTargetWrapper(new EventLogTarget())); LogAllRequests(pipelines); LogAllResponseCodes(pipelines); LogUnhandledExceptions(pipelines); } private void LogAllRequests(IPipelines pipelines) { pipelines.BeforeRequest += ctx => { log.Info("Handling request {0} \"{1}\"", ctx.Request.Method, ctx.Request.Path); return null; }; } private void LogAllResponseCodes(IPipelines pipelines) { pipelines.AfterRequest += ctx => log.Info("Responding {0} to {1} \"{2}\"", ctx.Response.StatusCode, ctx.Request.Method, ctx.Request.Path); } private void LogUnhandledExceptions(IPipelines pipelines) { pipelines.OnError.AddItemToStartOfPipeline((ctx, err) => { log.ErrorException(string.Format("Request {0} \"{1}\" failed", ctx.Request.Method, ctx.Request.Path), err); return null; }); }The tests should now pass and when you run the application log entries, they should be written to the Windows Event Log.
As an exercise, first add tests for
POST,PUT, andDELETErequests. Then add a test, which first makes a request that doesn't cause any exceptions and then checks that no logging error occurred.
Nancy sets up a pipeline to which all requests are sent through. At the center of the pipeline is the actual handler for the request. The pipeline hooks, we have seen, allows you to do things before the request reaches the handler and after the handler has returned a response, as well as doing other things in case the handler throws an exception.
In the hooks, we have access to NancyContext—the ctx variable in the previous code—which means that we have access to everything there is to know about the request: the HTTP method used, if it had form values, the body contents, the headers present, the module that handled it, the body of the response, the status code, the headers on the response, and so on.
In the previous code for the Before hook, we return null. This tells Nancy to keep running the pipeline. If on the other hand we return a Response, we implicitly tell Nancy that the request has now been handled and the response returned from the Before hook will be the response to the request. Similarly, we can return a Response from the OnError hook and have that sent back to the client allowing us to; for example, presenting custom error pages.
As mentioned at the beginning of this recipe there are similar Before, After, and OnError hooks that work on individual modules instead of the whole application.
Specifically for logging, it is worth noting that you can use ELMAH (http://code.google.com/p/elmah) with Nancy. Just install the Nancy.Elmah NuGet package and call ElmahLogging.Enable during the application start up. This will use the After and OnError hooks to set up ELMAH logging.