Loggning (ASP.NET WebApi serie 2/4)

I den här posten kommer vi att titta på två enkla mekanismer att använda för att lägga till audit-loggning och felhantering i sitt WebApi.

Loggning mha filter

Att logga inkommande anrop och utgående svarsresultat är extremt enkelt i ett ASP.NET WebApi-projekt genom att lägga till ett globalt filter i sin api-konfiguration. Detsamma gäller även för en ASP.NET MVC-applikation men all kod i det här exemplet kommer att vara skriven för ett WebApi.

Om man inte vet riktigt vad ett filter i ASP.NET WebApi/MVC är så kan man läsa om det här Understanding Action Filters och här Filters (ASP.NET Core).

Full .NET Framework (4.7)

Använder man Visual Studio för att skapa ett ASP.NET WebApi-project så kommer man att få en katalogstruktur i Solution Explorer som bland annat innehåller App_Start och i den ligger WebApiConfig.cs:
App_Start och WebApiConfig.cs i Solution Explorer

I WebApiConfig.cs, i den statiska klassen med samma namn, finns metoden Register som anropas från Application_Start i Global.asax.cs. Först i Register är det lämpligt att lägga i dom globala filtren som man vill att WebApi-controllers ska ha. I det här exemplet ser det då ut enligt:

public static void Register(HttpConfiguration config)  
{
      // Web API configuration and services
      config.Filters.Add(new LoggingActionFilter());

      // Web API routes
      config....
      .
      .
      .
}

Notera att ordningen man lägger till dom globala filtren i är den ordningen i vilken filtren exekverar.

I filtret, klassen LoggingActionFilter som ärver från ActionFilterAttribute, implementeras loggning i dom två metoderna OnActionExecuting och OnActionExecuted. Den första av dom två anropas av ramverket precis för anropet till API:ets action-metod och den andra efter det att action-metoden exekverats. Skelettet för filterklassen ser ut enligt:

public class LoggingActionFilter : ActionFilterAttribute  
{
    ...

    public override void OnActionExecuting(HttpActionContext actionContext)
    {
        try
        {
            // Logging goes here
            Logger.Instance.BeginRequest(actionContext, ...);
        }
        catch
        {
            // ignored, logging should not make the api die
        }

        base.OnActionExecuting(actionContext);
    }

    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        try
        {
            // Logging goes here
            Logger.Instance.EndRequest(actionExecutedContext, ...);
        }
        catch
        {
            // ignored, logging should not make the api die
        }

        base.OnActionExecuted(actionExecutedContext);
    }

    ...
}

Den kompletta koden för projektet finns i sin helhet här https://github.com/HeadlightAB/LoggingAndExceptionHandlingASPNetWebApi/tree/master/FullFrameworkLoggingUsingFilter, där även koden för loggern återfinns. Den loggar bara till Debug-output i exemplet.

I alla exemplen kommer de olika implementationerna av själva loggningen se relativt lika ut.

ASP.NET Core (2.0)

Loggningen i ASP.NET Core-versionen kommer att väldigt lik ut den som beskrevs ovan för det fulla .NET-ramverket. Man kan även här registrera globala filter i uppstarten av applikationen.

I ASP.NET Core finns dock inte lösningen med WebApiConfig-klassen utan här bygger webbapplikationerna på att man i uppstarten bygger upp sin request-response-pipeline, likt OWIN. Läs mer om pipelinen i ASP.NET Core här https://docs.microsoft.com/en-us/aspnet/core/fundamentals/startup.

När man lägger till MVC-stödet i ASP.NET Core's ServiceCollection i metoden ConfigureServices i Startup-klassen så lägger man även till det globala filtret:

public class Startup  
{
    .
    .
    .
    public void ConfigureServices(IServiceCollection services)
    {
        services.AddMvc(
            options => 
                // Logging using global action filter
                options.Filters.Add(typeof(LoggingFilterAttribute))
            );
    }
    .
    .
    .
}

Loggningen hakas alltså på genom LoggingFilterAttribute. Den här klassen ser mer eller mindre identisk ut med den som ligger med i exemplet för det fulla .NET-ramverket beskrivet ovan.

Det kompletta källkoden för det här avsnittets exempel finns här https://github.com/HeadlightAB/LoggingAndExceptionHandlingASPNetWebApi/tree/master/NetCoreLogging.

Notera att koden även implementerar loggningen med hjälp av ett middleware i request-response-pipelinen. Man bör såklart endast välja det ena eller andra sättet.

Loggning med hjälp av middleware

Loggning med hjälp av ett middleware i webbapplikationens pipeline är lika enkelt som loggning med hjälp av filter, beskrivet ovan.

Undrar man vad ett middleware är så kan man läsa på om t.ex. OWIN/Katana eller ASP.NET Core's implementation av OWIN. En bra start finns här https://docs.microsoft.com/en-us/aspnet/aspnet/overview/owin-and-katana/getting-started-with-owin-and-katana och här https://docs.microsoft.com/en-us/aspnet/core/fundamentals/middleware/.

Full .NET Framework (OWIN) middleware

För att kunna använda en OWIN pipeline i sin ASP.NET WebApi-applikation så krävs ett par olika nuget-paket:

  • Microsoft.Owin
  • Owin (dependency)

När paketen är installerade i projektet så kan man skapa en klass, OWIN Startup class:

using System.Web.Http;  
using Microsoft.Owin;  
using Owin;

[assembly: OwinStartup(typeof(FullFrameworkLoggingUsingOwin.Startup))]

namespace FullFrameworkLoggingUsingOwin  
{
    public class Startup
    {
        public void Configuration(IAppBuilder app)
        {
            var config = new HttpConfiguration();

            // Add logging middleware, before webapi
            app.UseLoggingMiddleware();

            WebApiConfig.Register(config);
            app.UseWebApi(config);
        }
    }
}

Ett par saker är värda att notera här:

  • [assembly:OwinStartup....] gör att metoden Configuration anropas av ramverket
  • WebApiConfig.Register(config) är tagen från Global.asax.cs, som i det här exemplet är helt tom
  • app.UseWebApi(...) talar om att WebApi ska vara en del av OWIN pipeline
  • Ordningen i vilken middlewares läggs till har betydelse, då dessa kommer att exekveras i just den ordningen

I Startup-klassen återfinns anropet till UseLoggingMiddleware. Denna metoden är en extension-metod till IAppBuilder. I exemplet här ligger denna extension och middleware för loggningen i samma klassfil:

using System;  
using System.Diagnostics;  
using System.Threading.Tasks;  
using Microsoft.Owin;  
using Owin;

namespace FullFrameworkLoggingUsingOwin  
{
    public static class LoggingMiddlewareExtensions
    {
        public static void UseLoggingMiddleware(this IAppBuilder app)
        {
            app.Use<LoggingMiddleware>();
        }
    }

    internal class LoggingMiddleware : OwinMiddleware
    {
        public LoggingMiddleware(OwinMiddleware next) : base(next)
        {}

        public override async Task Invoke(IOwinContext context)
        {
            var correlationId = Guid.NewGuid().ToString();

            var request = context.Request;

            var user = context.Request.User.Identity.IsAuthenticated
                ? context.Request.User.Identity.Name
                : "anonymous";

            Debug.WriteLine($"BeginRequest logging: {correlationId} - {request.Method} @ {request.Uri} by {user}");

            await Next.Invoke(context);

            Debug.WriteLine($"EndRequest logging: {correlationId} - response is {context.Response.StatusCode} {context.Response.ReasonPhrase}");
        }
    }
}

Här noterar vi:

  • Debug.WriteLine($"BeginRequest...") loggar inkommande request
  • await NextInvoke(context) passar requesten vidare genom pipeline
  • Debug.WriteLine($"EndRequest...") loggar utgående svar

Just dom här tre raderna kod kan öka förståelsen för vad en OWIN pipeline är; man får requesten till sig, kan göra något med den, skickar den vidare in i pipan och kan efter man kommer tillbaka via await välja att göra något på request-response "på vägen ut".

Vill man vara noggrann i sitt middleware och inte låta loggning krascha applikationen så lägger man med fördel ett try-catch-block kring respektive loggningsmetod. Dock INTE kring hela sin Debug-await Next-Debug eftersom man då kan få en applikation som inte säger något alls vid fel.

Komplett källkod för det här exemplet återfinns här https://github.com/HeadlightAB/LoggingAndExceptionHandlingASPNetWebApi/tree/master/FullFrameworkLoggingUsingOwin.

ASP.NET Core (2.0) middleware

En implementation av OWIN är inbyggd i ASP.NET Core, från första versionen, vilket gör att lösningen beskriven ovan för det fulla .NET-ramverket är mer eller mindre direkt applicerbart här. Om man i Visual Studio väljer att skapa ett ASP.NET Core-projekt så får man i mallen med en Startup-klass. Vi tittade på den i exemplet för loggning mha filter i en ASP.NET Core-applikation ovan.

I Startup-klassen för ASP.NET Core finns en Configure-metod, liknande Configuration i fulla ramverkets OWIN/Katana-implementation:

public void Configure(IApplicationBuilder app, IHostingEnvironment env)  
{
    if (env.IsDevelopment())
    {
        app.UseDeveloperExceptionPage();
    }

    app.UseLoggingMiddleware(); // Logging using middleware

    app.UseMvc();
}

app.UseLoggingMiddleware() är en extensionmetod på IApplicationBuilder och lägger till loggningen i pipeline:

using System;  
using System.Diagnostics;  
using System.Threading.Tasks;  
using Microsoft.AspNetCore.Builder;  
using Microsoft.AspNetCore.Http;

namespace NetCoreLogging  
{
    public static class LoggingMiddlewareExtensions
    {
        public static void UseLoggingMiddleware(this IApplicationBuilder app)
        {
            app.UseMiddleware<LoggingMiddleware>();
        }
    }

    public class LoggingMiddleware
    {
        private readonly RequestDelegate _next;

        public LoggingMiddleware(RequestDelegate next)
        {
            _next = next;
        }

        public async Task Invoke(HttpContext context)
        {
            var correlationId = Guid.NewGuid().ToString();
            var request = context.Request;
            var user = context.User.Identity.IsAuthenticated ? context.User.Identity.Name : "anonymous";

            Debug.WriteLine($"BeginRequest logging: {correlationId} - {request.Method} @ {request.Path} by {user}");

            await _next(context);

            Debug.WriteLine($"EndRequest logging: {correlationId} - response is {context.Response.StatusCode}");
        }
    }
}

Precis som i exemplet för det fulla .NET-ramverket så finns dom tre raderna som gör jobbet med inkommande request och utgående response:

  • Debug.WriteLine($"BeginRequest...") loggar inkommande request
  • await _next(context) passar requesten vidare genom pipeline
  • Debug.WriteLine($"EndRequest...") loggar utgående svar

Värt att notera är att middleware i ASP.NET Core är vanliga klasser som innehåller en konstruktor med en parameter RequestDelegate och en metod Invoke som tar en Context som parameter. By-convention så kan en sådan klass läggas till som ett middleware i pipeline.

Komplett källkod för ASP.NET Core-exemplet finns här https://github.com/HeadlightAB/LoggingAndExceptionHandlingASPNetWebApi/tree/master/NetCoreLogging.

Tillbaka till introduktionen.