Automating Logging of Security Failures in ASP.NET MVC

There are three main reasons for logging and tracing in applications:

1. You need to log errors
2. You need to track performance
3. You need to track unusual system behaviour

I’m sure you can think of other reasons, but these cover most scenarios and it’s the latter that we’ll look at today, on day 22 of our advent calendar.

The idea of tracking unusual behaviour isn’t one you most often think of when logging, but it can be useful for identifying things such as users consistently forgetting password (we’ve all done it), or more worryingly, an attempt to hack into your system. A string of security failures in quick succession could identify something like a bot attempting to break in. Not only is this an issue you need to address for security reasons, but it could also impact the performance of your application. There are two things you’d want to track:

1. Authentication Failures. This needs to track both the creation of accounts (if that is a public feature of your site) as well as failed login attempts.
2. Authorisation Failures. This shows attempts to access parts of a site that the user isn’t allowed to access, and could show an attempt to find an unsecured page.

The first of these is a manual affair, where you’d add logging code to your actions (or business logic methods) that deal with the account logic. For example, a typical LogOn action could be:

[HttpPost]
public ActionResult LogOn(LogOnModel model, string returnUrl)
{
  if (ModelState.IsValid)
  {
    if (Membership.ValidateUser(model.UserName, model.Password))
    {
      // snip - code if the validation passes
    }
    else
    {
      ModelState.AddModelError("",
        "The user name or password provided is incorrect.");
      <strong>Gibraltar.Agent.Log.Warning("Account", "User Validation", "Account validation for user '{0}' failed", model.UserName);</strong>
    }
  }

  // If we got this far, something failed, redisplay form
  return View(model);
}

The important thing here is the logging added on failure. You’ll now see any security failures as warnings in your Gibraltar logs. You could of course, use Error instead of Warning if you wanted.

The second issue, that of authorisation, can be done automatically, but requires code to plug into the automatic authorization system. One way to do this would be to create a new filter attribute that just checks if authorisation is granted and logs it if not, but this would require two attributes: The Authorize attribute and the logging one. A simpler solution is to create a new attribute that does both. For example:

public class AuthorizeAndLog : AuthorizeAttribute
{
  protected override bool AuthorizeCore(HttpContextBase httpContext)
  {
    var authorized = base.AuthorizeCore(httpContext);

    if (!authorized)
    {
      var userName = httpContext.User.Identity.IsAuthenticated
                     ? "anonymous"
                     : httpContext.User.Identity.Name;

      Gibraltar.Agent.Log.Warning("Security", "Authorization",
                "Authorization failure for " + userName);
    }

    return authorized;
  }
}

Now, instead of using the Authorize attribute, you use AuthorizeAndLog. Eg:

[AuthorizeAndLog]
public ActionResult About()
{
  return View();
}

[AuthorizeAndLog(Roles = "Admin")]
public ActionResult SecretStuff()
{
  return View();
}

This performs exactly the same action as Authorize, but additionally logs any failures. So with a small amount of code, you can track security failures at different points in your application. Easy, isn’t it?