Nozus Step 2: Setting up MVC 6 with Basic Logging

The previous post in this series covered basic MVC 6 API project setup. In this post, we’re going to build on that and set up some baseline logging functionality in the API.  We’ll continue to enhance logging as the project progresses.

We’ll start by setting up logging.  In our case, we’re going to use Serilog.  It’s the new kid on the block for .Net logging and looks like it combines some nice elements of structured data with basic log messages.  This can easily be swapped for NLog.  Right now there isn’t 5.0 support for Log4Net, but expect that to change.

If it’s not already available, open the Package Manager Console: Tools –> Nuget Package Manager –> Package Manager Console. In the package source, select your VNext package source and the Web.Api project. At the prompt:

PM> Install-Package Microsoft.Framework.ConfigurationModel.Json -includeprerelease
Installing NuGet package Microsoft.Framework.ConfigurationModel.Json.1.0.0-beta3.
PM> Install-Package Microsoft.Framework.Logging.Serilog -includeprerelease
Installing NuGet package Microsoft.Framework.Logging.Serilog.1.0.0-beta3.

So we just installed JSON configuration support (no more web.config) and support for Serilog.  Now lets add a config.json file.  Right click on the Web.Api project and Select Add –> New Item…  Select ASP.Net Configuration File.  This should correspond to a config.json file.  Just add the default json.config to the project, we’ll add some things to it in a later installment.  I lowercase the file name…optional.

We’re going to add logging into the Startup.cs now. Open Startup.cs, add a Configuration property, and set it in the constructor. This will set up config information from our config.json and will also add configuration in from any environment variables that may be set in the deployment environment.

 public Startup(IHostingEnvironment env)
 {
   // Setup configuration sources.
   Configuration = new Configuration()
   .AddJsonFile("config.json")
   .AddEnvironmentVariables();
 }

 public IConfiguration Configuration { get; set; }

Now we’ll update the ConfigureServices method.  Configure services sets up services in our DI container.  We’ll add in logging by calling AddLogging() and while we’re in here, we’ll go ahead and remove XML as a potential output format. Notice that AddLogging reads in the configuration we read in the constructor.  We’re going JSON only with these services. Why? Because I don’t really want to support XML. Leave it if you like.

 public void ConfigureServices(IServiceCollection services)
 {
 services.AddLogging(Configuration);
 services.AddMvc();
 services.Configure<MvcOptions>(options =>
 {
 options.OutputFormatters.RemoveAll(formatter =>
formatter.Instance is XmlDataContractSerializerOutputFormatter);
 });
 }

Next, we’ll configure the actual middleware pipeline.  For this we use the Configure method. It’s a little confusing that we have ConfigureServices (DI) and Configure (Pipeline), but that’s the convention.  We’ll add Serilog as our logger and create a method to set up our logger configuration. Serilog can alternately read from app settings if that is preferred and I’ll probably switch it over to do that at some point.  Notice here that I’m writing out to a rolling file on my D drive.  You can write to whatever location or writer works for you.

public void Configure(IApplicationBuilder app,
IHostingEnvironment env, ILoggerFactory loggerFactory)
{
  loggerfactory.AddSerilog(GetLoggerConfiguration());
  app.UseStaticFiles();
  // Add MVC to the request pipeline.
  app.UseMvc(routes =>
  {
    routes.MapRoute(
    name: "default",
    template: "{controller}/{action}/{id?}",
    defaults: new {
        controller = "Home",
        action = "Index" });
  });
}

private static LoggerConfiguration GetLoggerConfiguration()
{
 return new LoggerConfiguration()
 .Enrich.WithMachineName()
 .Enrich.WithProcessId()
 .Enrich.WithThreadId()
 .MinimumLevel.Debug()
 .WriteTo.RollingFile(@"D:\Logs\Nozus.Web.Api\file-{Date}.txt",
 outputTemplate:
 "{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz} {Level}:{EventId} [{SourceContext}] {Message}{NewLine}{Exception}")
}

Now that we have the Serilog package installed, if you try to compile you might notice a problem.  The compiler has some complaints and if you look closely, you’ll notice that it’s complaining about Serilog but in addition that it’s complaining about ASP.Net Core 5.0.

So if you’re not already aware, we have two flavors of .Net 5.0, the core flavor, which is being touted as the minimal/side-by-side/deployable/cloud flavor vs the full framework.  The problem here is that Serilog (and most other legacy .Net assemblies) won’t be compatible with the core flavor.  Expect this to change as .Net 5.0 goes live and the migration begins.  Right now we are compiling for both the Core and full flavors of the framework.  For now, we’re going to remove Core compilation from our project.  Open the project.json file and delete the core framework:

 "frameworks": {
     "aspnet50": { },
     "aspnetcore50": { }
 }

Now compilation should succeed.  Now let’s put in some basic logging to do an error catch all.  So there are a few ways to accomplish this.  One was is to use the built in ErrorHandling middleware.  To me, this is more geared towards MVC, where one wants to perform some logging and then perhaps render an alternate view from the standard. In my case since this is an API, I just want to log the error and send the standard 500 error out the door.  Perhaps I’ll add in a Production mode later that sends an alternate view out.  The nice thing is that since ASP.Net is now open source, we can see what the error handling middleware does and just make a simpler version of this when configuring services.  Since I just need something stupid simple, I added my own middleware.

In the Web.Api project add a Middleware folder.  In this folder create a new class called ErrorLoggingMiddleware.  It should look like this:

using System; using System.Threading.Tasks;
using Microsoft.AspNet.Builder;
using Microsoft.AspNet.Http;
using Microsoft.Framework.Logging; 

namespace Nozus.Web.Api.Middleware
{
public class ErrorLoggingMiddleware
{
private readonly RequestDelegate _next;
private readonly ILogger _logger;
public ErrorLoggingMiddleware(RequestDelegate next,
ILoggerFactory loggerFactory)
{
  _next = next;
  _logger = loggerFactory.Create<ErrorLoggingMiddleware>();
} 

public async Task Invoke(HttpContext context)
{
  try
  {
    await _next(context);
  }
  catch (Exception ex)
  {
    _logger.WriteError("An unhandled exception has occurred: "
    + ex.Message, ex);
    throw; // Don't stop the error
  }
}
}
}

All we’re doing is logging the error and throwing it up the chain for eventual handling by the framework. One really nice thing is that you’ll notice our dependencies are injected into the middleware for us.  So middleware is now hooked into the core DI mechanism and is truly first class.  Very nice…  You can also see the basic middleware pattern.  This is the same basic OWIN pattern you may be used to: Middleware is a russian doll where the next middleware component is injected and wrapped by the current middleware component.  So in our case we just call the next middleware component and log something if there’s an error. Really easy, the possibilities for open-source/third-party middleware are huge.  I expect this to explode with Asp.Net 5.

So now we need to call our middleware.  In the Configure method, well use the AddMiddleware method to add in our custom middleware.

public void Configure(IApplicationBuilder app, 
IHostingEnvironment env, ILoggerFactory loggerFactory)
 {
 loggerFactory.AddSerilog(GetLoggerConfiguration());

 app.UseStaticFiles();
 // Add MVC to the request pipeline.

 app.UseMiddleware<ErrorLoggingMiddleware>();

 app.UseMvc(routes =>
 {
   routes.MapRoute(
   name: "default",
   template: "{controller}/{action}/{id?}",
   defaults: new { 
        controller = "Home", 
        action = "Index" });
 });
 }

So easy and now we’re set.  One thing to remember is that the order of adding middleware determines the call sequence, so it’s important to add your component in the right place, which may differ depending on what you are trying to accomplish.

So now as a quick example, let’s log something from our home page by throwing an error from our default HomeController.  Just open the HomeController and have the Index method throw an error, something like:

[HttpGet("/")]
 public IActionResult Index()
 {
 throw new InvalidOperationException("Ghost in the machine!");
 return View();
 }

Let’s start up our app and it should immediately err since the error message gets thrown up the chain by our middleware.

But if we go to our log file location that we set earlier, we should now have a log file with our error properly logged.

2015-03-11 21:02:58.723 -05:00 Error: [Nozus.Web.Api.Middleware.ErrorLoggingMiddleware] An unhandled exception has occurred: Ghost in the machine!
System.InvalidOperationException: Ghost in the machine!
 at Nozus.Web.Api.Controllers.HomeController.Index() in C:\Users\Visual Studio 14\Projects\Another\Nozus.Web.Api\Controllers\HomeController.cs:line 14
--- End of stack trace from previous location where exception was thrown --etc....

Just remember to remove the thrown error before proceeding further….in the next installment we’ll set up basic identity management…then we may switch over to Aurelia before getting back to social logins.