Audit Logging using ASP.NET MVC 4 ActionFilter

Question

I'm building a web app using ASP.NET MVC 4, with data storage provided by T-SQL database via Entity Framework. I'm integrating audit logging as I go, and I'd like to provide a nice human-readable summary of the action, so that I can present a friendly logs view with clear statements like "User Bob logged in", "User Alice updated article 'Foo'", etc.

An audit record currently consists of:

• GUID
• timestamp
• user ID
• action category (controller name)
• action (action method name)
• IsError (boolean; true means either this is a record of an error, or this action did not complete successfully)
• blob of serialised details

At the moment, my logging uses a custom attribute which implements IActionFIlter; the OnActionExecuting() method logs the attempted action (serialising things like URL, parameters etc to the detail blob) and the OnActionExecuted() method goes back and sets IsError to true if there are no errors, and appends either the returned result or exception with error message and stack trace etc to the details. I want to add another column for description strings, but I can't see a tidy way to do it.

The furthest I got was to pass a string to the attribute, something like "User $user logged in" and then have the log method scan the string for the $ character and replace that word with anything from the parameters dictionary whose key value matches that word (minus the $ character). This is a little limited; for example, if articles are stored by ID number, then the best you can manage is "User 18 edited article 37". There's no real way to get at the username or article title; you can't pass instance data to the attribute because it's baked in at compile time, and I don't really want my logging method to be making all sorts of database calls to get that sort of data, not least because it then becomes impossible (or at least a real pain) to have a single generic logging method.

The alternative to all this is to have a static audit logging class and call something like AuditRecord.WriteLog(foo); all over the place, perhaps with some kind of descriptor class I can use (or inherit from) to describe different types of action, storing all the parameters and generating a description string as needed, but seems less elegant to me; I really like being able to just tag [AuditLog] on top of a method and know that it'll be recorded.

I'd like to avoid huge amounts of conditional logic, like using the controller and action names in some big switch statement to select the correct string template. If I could just get hold of things like article titles in the logging method then it'd be fine. Is there a neat, simple way to do this?

Answer 1

We recently had a similar discussion at work regarding both logging audit history and applying more complex security rules across our new MVC project.

In the end the most "elegant" solution that we came up with was to have the method calls within the controller actions (Your alternative method).

For example:

[HttpPost]
public ActionResult CreateItem(Item item)
{
    //Simplified
    CheckSecurity(SecurityTypes.ItemCreation);
    LogActivity("Created an item");

    //Rest of action code

}

This gave us the flexibility to account for all possible use cases, and allowed us to wrap up the logic into simple to use methods to reduce code repetition.

Answer 2

It may be late to answer, but I think there is a good alternative to keep using action filter attributes and to be able to access per-request lifecycle objects.

As anaximander noted it above, the underlying problem is that attributes are resolved by the CLR, so their lifetime cannot be controlled and they don't mix very well with an IoC container (to make them transient, per request instance, etc.).

Usually, in .NET a new instance of attribute is created each time it is resolved by reflection (GetCustomAttribute method).

Furthermore, in the case of MVC/webapi, action filter attributes are cached, so they normally are created just once.

The conclusion is that attributes are designed to annotate only, in other word, they should contain only metadata (they are DTO). Unfortunately, my understanding is MVC and WebApi frameworks are not designed in this way. To restrict action filter attributes to simple DTOs and to be able to manage lifecycle of the logic part around them, special means must be taken.

I think your use case fits perfectly to the solution provided in a Steven van Deursen's great article. It demonstrates how to separate attributes data from logic and it is based on an action filter registered globally, the so called "dispatcher", with the ioc container as a dependency. The container is not resolved statically. It is provided in the constructor of the global filter when it is registered at the application initialization. So each time it is executed, it looks for any attribute marker on the action being executed and it resolves a generic interface where the attribute is the generic parameter. Instead of having an action filter attribute which merge data and behavior, you end up using two classes: a plain old attribute - the marker - and the corresponding implementation of the generic interface for its logic counterpart. The container is used to resolve the generic interface. If your filter depends on per-request components, you can create an implementation of the generic interface with the services you need. If it does not depend on other services but you need a per-request lifetime (to measure time between the beginning and the end of an action for example), it also does the job, thank to the use of the container to resolve the generic interface. The aforementioned article contains code examples for WebApi, MVC and ASP.NET 5.

Also, Mark Seemann has made an article on the same approach.

I think it does not provide a good solution for all cases, like authorizations filters and perhaps exception filters, but to me it is the most elegant way for many action filters.

Answer 3

The better way would be to format this data when you view it, rather than build these things during the logging process.

If the action is "login", and the recorded user is available (which you should do) then you build that message in the viewer.

So you log all the raw events, then build the "view model" or "read model" based on this data that is more descriptive. this can allow you to even re-parse all the raw data if you want to change it's description. You could log a lot of data that isn't used yet so you could implement it later within the description.

IMO, sprinkling methods this way inside actions doesn't seem like a good idea and an Action Filter on the controller or base controller is cleaner. if you wanted to do that you could use an AOP (aspect oriented programming) framework to avoid cross cutting...