Motivation for Logging
Logging is the one thing you don’t know you need until you need it. I’m sure many of us have all been in the situation in which you wish you knew what your program was doing in a production environment. If only you could set a break point to check all of your variables and figure out why you can’t recreate it on your machine. One of the best solutions to this situation is logging! Good logging can often help you know exactly why that exception occurred. You can write logs as granular as you need. You can even set logging up so that different levels are logged based on a setting, either from a web.config file or a database. Some the reasons I can think of off the top of my head are:
- Debugging purposes
- Auditing user access
- Performance metrics
- Usability assessment
- Supplement to commenting your code
I stumbled across another blog by Erik Hazzard in which he goes into more detail about why logging is important. vasir.net/blog/development/how-logging-made-me-a-better-developer
Today I am going to show you my simple logging and audit solution. I know there are many enterprise level logging solutions out there, such as Log4Net, but those are over kill for my needs and writing this takes just as much time as integrating a third party framework. I am using Entity Framework with my ASP.NET MVC project. I am also using Unity for dependency injection, in case the usage below is unclear. I wanted an easy way to be able to write log entries and automatically collect information on my controllers and their actions with the minimum amount of effort. My project has three main layers. The model layer, where I keep all my entities and class that describe my domain. The data layer keeps all my repositories and contexts for actually writing and saving data, it does a nice job of decoupling my data access from the rest of my code. My last main layer is the actual MVC project that contains all of my controllers, HTML and JavaScript.
Model/Entity
Here I have a simple log entry object, which has the properties that I am most interested in logging.
public class LogEntry { public int Id { get; set; } public string UserName { get; set; } public string Message { get; set; } public string Controller { get; set; } public string Action { get; set; } public string IP { get; set; } public DateTime DateTime { get; set; } public LogType LogType { get; set; } } public enum LogType { ControllerAction, UserEvent, EntityFrameWork, Exception }
Here you can see I want to track things like the user who is logged in, the name of the current controller and action, the date and time, a message, and what type of log event this is. Nice and simple! It will be easy to add more properties in the future if I have a need for extra information.
Data Layer
Here is my simple context which Entity Framework’s code first will use when creating the LogEntries table. The LogEntryConfiguration simply sets the Id as required, so I am not going show that here.
public class LoggingContext : DbContext { public LoggingContext() : base("DefaultConnection") { } public DbSet<LogEntry> LogEntries { get; set; } protected override void OnModelCreating(DbModelBuilder modelBuilder) { modelBuilder.Configurations.Add(new LogEntryConfiguration()); } }
In my data layer I have a repository for logging that allows me to do CRUD like operations. The interface allows me to decouple the consuming code from the actual implementation of the logging. This will make changing to some other logging mechanism, such as writing to a text file or another database, a piece of cake, as none of the calling code will have to change.
public interface ILogEntryRepository { IEnumerable<LogEntry> GetAllLogEntries(); IEnumerable<LogEntry> GetAllLogEntriesForLogType(LogType logType); IEnumerable<LogEntry> GetAllLogEntriesForLogTypeInDateRange(LogType logType, DateTime startDate, DateTime endDate); IEnumerable<LogEntry> GetAllLogEntriesInTimeRange(DateTime startDate, DateTime endDate); LogEntry InsertLogEntry(LogEntry logEntry); void LogMessage(string message); }
Below is the interface I defined that my log entry repository implements. I have several methods for viewing and filtering log entries that I use on a dashboard. The main method, which we are concerned about here, is the InsertLogEntry method. This method simply takes a LogEntry and saves it to the database. I am injecting the LoggingContext in through my constructor and am using that instance in all my methods for database communication. As you can see the code is simple and straight forward.
public class LogEntryRepository : ILogEntryRepository { private LoggingContext context; public LogEntryRepository(LoggingContext context) { this.context = context; } public IEnumerable<LogEntry> GetAllLogEntries() { return context.LogEntries.OrderByDescending(x => x.DateTime).ToList(); } public IEnumerable<LogEntry> GetAllLogEntriesForLogType(LogType logType) { return context.LogEntries.Where(x => x.LogType == logType).OrderByDescending(x => x.DateTime).ToList(); } public LogEntry InsertLogEntry(LogEntry logEntry) { logEntry = context.LogEntries.Add(logEntry); context.SaveChanges(); return logEntry; } public void LogMessage(string message) { LogEntry logEntry = new LogEntry() { Message = message, DateTime = DateTime.Now, LogType = LogType.EntityFrameWork }; context.LogEntries.Add(logEntry); context.SaveChanges(); } public IEnumerable<LogEntry> GetAllLogEntriesForLogTypeInDateRange(LogType logType, DateTime startDate, DateTime endDate) { return context.LogEntries.Where(x => x.LogType == logType && x.DateTime.Date <= endDate.Date && x.DateTime.Date >= startDate).OrderByDescending(x => x.DateTime).ToList(); } public IEnumerable<LogEntry> GetAllLogEntriesInTimeRange(DateTime startDate, DateTime endDate) { return context.LogEntries.Where(x => x.DateTime.Date <= endDate.Date && x.DateTime.Date >= startDate).OrderByDescending(x => x.DateTime).ToList(); } }
MVC Project/Consumer
One place where I consume my logging repository, is in a custom ActionFilter. This ActionFilter automatically logs any time a controller’s action is entered. This filter just populates a LogEntry object in the OnActionExecuting method, which fires when a method on a controller is hit. My filter is making use of Setter Injection using the [Dependency] attribute that comes with Unity, my IoC container, to set my LogEntryRepository. After creating a LogEntry object all I need to do is call my repository and insert the log entry.
public class LogFilter : ActionFilterAttribute, IActionFilter { [Dependency] public ILogEntryRepository LogEntryRepo { get; set; } void IActionFilter.OnActionExecuting(ActionExecutingContext filterContext) { LogEntry log = new LogEntry() { UserName = filterContext.HttpContext.User.Identity.Name, Controller = filterContext.ActionDescriptor.ControllerDescriptor.ControllerName, Action = filterContext.ActionDescriptor.ActionName, IP = filterContext.HttpContext.Request.UserHostAddress, DateTime = DateTime.Now, LogType = LogType.ControllerAction }; LogEntryRepo.InsertLogEntry(log); this.OnActionExecuting(filterContext); } }
All I have to do is decorate a controller/action method with this LogFilter attribute and presto, detailed information is logged to the database. What could be less painful?
[LogFilter] public class ItemController : Controller {
The Output
Here is an image of my SQL database after running through my application. Near the bottom, you can see two log messages that are the result of exceptions being triggered. The entry contains the exception message and the LogType is set to 3, based on my enumerations. All of the IP’s are shown as ::1 because I was running locally.
I hope you found this solution helpful and/or inspiring to help you create or expand on your own logging implementation. I would like to know about the logging solutions you are currently using and when it has come in handy the most. Let me know in the comments or on Twitter @ScottKerlagon!
Also let me know if you would like me to cover some of the concepts I used such as dependency injection and the repository pattern in future posts.