Sunday, March 24, 2013

Implementing a simple logging engine with MVC 4

I was investigating the simple logging mechanism for the MVC application. First I came up with some requirements for the logging engine:

High-level requirements:

  • Create logging engine that can log exceptions and other messages and store them in the database
  • Display a filterable grid of all messages

Logging engine

  • Should allow logging of exceptions, including handled and unhandled
  • Should allow logging of custom messages

Filterable grid

  • Should allow paged display of all exceptions and log messages in the database
  • Should allow the option to filter messages based on the date logged and severity

I started with these simple classes that will allow handling of messages and exception:

//actual entry, each will correspond to a line in the grid
public class LogEntry
{
 public int Id { get; set; }
 public DateTime TimeStamp { get; set; }
 public string Path { get; set; }
 public string RawUrl { get; set; }
 public string Source { get; set; }
 public string Message { get; set; }
 public string StackTrace { get; set; }
 public string TargetSite { get; set; }

 public int TypeId { get; set; }
 public virtual LogType LogType { get; set; }
}

//a "helper" class for types like Warning, Information etc.
public class LogType
{
 public int LogTypeId { get; set; }
 public string Type { get; set; }
}

//finally, an enum of all supported log message types
public enum LogTypeNames
{
 All = 0,
 Info = 1,
 Warn = 2,
 Debug = 3,
 Error = 4,
 Fatal = 5,
 Exception = 6
}

These will be reflected in two database tables - the main table for saving all log messages, and a helper table to keep names of message severity levels.

public DbSet<LogType> LogTypes { get; set; }
public DbSet<LogEntry> LogEntries { get; set; }

Next, it is time to mention logging of handled and unhandled exceptions, which can be divided into handled and unhandled exceptions.

Develop mechanism for logging exceptions:

1. Log unhandled exceptions

Unhandled exceptions are, well, exceptions that are not handled in the source code. First, the site web.config must be modified to add a line in the section:

Here's how it works: a method is called in Global.asax file:

public static void RegisterGlobalFilters(GlobalFilterCollection filters)
{
    filters.Add(new HandleErrorAttribute());
}

It registers the HandleErrorAttribute as global action filter. The HandleErrorAttribute checks the customErrors mode, and if it is off, shows the "yellow screen of death". If it is on, the Error view is rendered and a Model is passed to it containing exceptions stack trace. Therefore, an Error.cshtml should be added under Views/Shared, and in its simplest form may look as follows

@using Recipes.Logging
@using Recipes.Models
@{
    Layout = null;
    ViewBag.Title = "Error";
    Logger.WriteEntry(Model.Exception);
}

<!DOCTYPE html>
<html>
<head>
    <title>Error</title>
</head>
<body>
    <h2>
        Sorry, an error occurred while processing your request. The details of the error were logged.
    </h2>
</body>
</html>

For simplicity, all log messages - exceptions, handled and unhandled, and all other custom messages - will be saved in a single database table.

2. Log handled exceptions

The handled exceptions are caught by code and handled directly. The following is the Logger class which handles exceptions and custom messages and saves them to the database:

public static class Logger
{
 public static void WriteEntry(Exception ex)
 {
  LogEntry entry = BuildExceptionLogEntry(ex);
  SaveLogEntry(entry);        
 }

 public static void WriteEntry(string mesage, string source, int logType)
 {
  LogEntry entry = BuildLogEntry(mesage, source, logType);
  SaveLogEntry(entry);
 }

 private static void SaveLogEntry(LogEntry entry)
 {
  using (RecipesEntities context = new RecipesEntities())
  {
   context.LogEntries.Add(entry);
   context.SaveChanges();
  }
 }

 private static LogEntry BuildLogEntry(string message, string source, int logType)
 {
  LogEntry entry = BuildLogEntryTemplate();

  entry.Message = message;
  entry.Source = source;
  entry.LogType = GetLogEntryType((LogTypeNames)logType);
  entry.TypeId = logType;

  return entry;
 }

 private static LogEntry BuildExceptionLogEntry(Exception x)
 {
  Exception logException = GetInnerExceptionIfExists(x);
  LogEntry entry = BuildLogEntryTemplate();

  entry.Message = logException.Message;
  entry.Source = logException.Source ?? string.Empty;
  entry.StackTrace = logException.StackTrace ?? string.Empty;
  entry.TargetSite = logException.TargetSite == null ? string.Empty : logException.TargetSite.ToString();
  entry.LogType = GetLogEntryType(LogTypeNames.Exception);
  entry.TypeId = (int) LogTypeNames.Exception;

  return entry;
 }

 private static LogEntry BuildLogEntryTemplate()
 {
  return new LogEntry
       {
        Path = HttpContext.Current.Request.Path,
        RawUrl = HttpContext.Current.Request.RawUrl,
        TimeStamp = DateTime.Now,
       };
 }

 public static string BuildExceptionMessage(Exception x)
 {
  Exception logException = GetInnerExceptionIfExists(x);

  string strErrorMsg = Environment.NewLine + "Error in Path :" + HttpContext.Current.Request.Path;
  // Get the QueryString along with the Virtual Path
  strErrorMsg += Environment.NewLine + "Raw Url :" + HttpContext.Current.Request.RawUrl;
  // Get the error message
  strErrorMsg += Environment.NewLine + "Message :" + logException.Message;
  // Source of the message
  strErrorMsg += Environment.NewLine + "Source :" + logException.Source;
  // Stack Trace of the error
  strErrorMsg += Environment.NewLine + "Stack Trace :" + logException.StackTrace;
  // Method where the error occurred
  strErrorMsg += Environment.NewLine + "TargetSite :" + logException.TargetSite;
  return strErrorMsg;
 }

 private static LogType GetLogEntryType(LogTypeNames name)
 {
  return new LogType{LogTypeId = (int)name, Type = name.ToString()};
 }

 private static Exception GetInnerExceptionIfExists(Exception x)
 {
  if (x.InnerException != null)
   return x.InnerException;
  return x;
 }
}

With this basic structure in place, I can start adding user interface for displaying the log. I decided to only have two views, Index for the main grid which contains all log messages, and a Details for a detailed information about a single message. Details will be linked from the line in a grid that corresponds to a log message.

Index view.

The view will have several main parts, wrapped in a form.

@using (Html.BeginForm("Index", "Logging", new { CurrentPageIndex = 1 }, FormMethod.Get, new { id = "myform" }))
{

}

First is the div that shows the number of records found and gives an option to choose how many records per page will be displayed.

<div class="grid-header">
    <div class="grid-results">
        <div class="inner">
            <span style="float: left">
                @string.Format("{0} records found. Page {1} of {2}", Model.LogEvents.TotalItemCount, Model.LogEvents.PageNumber, Model.LogEvents.PageCount)
            </span>

            <span style="float: right">
                Show @Html.DropDownListFor(model => model.PageSize, new SelectList(FormsHelper.PagingPageSizes, "Value", "Text", Model.PageSize), new { onchange = "document.getElementById('myform').submit()" }) results per page
            </span>
            
            <div style="clear: both"></div>
        </div> <!-- inner -->
    </div>  <!-- grid-results -->
 </div>  <!-- grid-header -->

The second allows to filter records by date logged and severity

 <div class="grid-filter">        
    <div class="inner">
        Level : @Html.DropDownList("LogLevel", new SelectList(FormsHelper.LogLevels, "Value", "Text"))

        For : @Html.DropDownList("Period", new SelectList(FormsHelper.CommonTimePeriods, "Value", "Text"))
        
        <input id="btnGo" name="btnGo" type="submit" value="Apply Filter" />                      
    </div>
 </div>   

Next is the "pager" div, which allows navigation if multiple pages are reqiured

  <div class="paging">
    <div class="pager">
        @Html.Pager(ViewData.Model.LogEvents.PageSize, ViewData.Model.LogEvents.PageNumber, ViewData.Model.LogEvents.TotalItemCount, new { LogType = ViewData["LogType"], Period = ViewData["Period"], PageSize = ViewData["PageSize"] })
    </div>
 </div>

Finally, the main part is the actual grid which displays the messages.

 @if (Model.LogEvents.Count() == 0)
 {
 <p>No results found</p>
 }
 else
 {
 <div class="grid-container">
 <table class="grid">
    <tr>
        <th></th>
        <th>#</th>
        <th>Source</th>
        <th>Date</th>
        <th style='white-space: nowrap;'>Time ago</th>
        <th>Message</th>
        <th>Type</th>
    </tr>

 @{int i = 0;}
     @foreach (var item in Model.LogEvents)
     {
     <tr class="@(i++ % 2 == 1 ? "alt" : "")">
     <td>
        @Html.ActionLink("Details", "Details", new { id = item.Id.ToString(), loggerProviderName = "Go To Details" /*item.LoggerProviderName*/ })
     </td>
     <td>
        @i.ToString()
     </td>
     <td>
        @item.Source
     </td>
     <td style='white-space: nowrap;'>
        @String.Format("{0:g}", item.TimeStamp.ToLocalTime())
     </td>
     <td style='white-space: nowrap;'>
        @item.TimeStamp.ToLocalTime().TimeAgoString()
     </td>
     <td>
        <pre>@item.Message.WordWrap(80)</pre>
     </td>
     <td>
        @item.LogType.Type
     </td>
     </tr>
     }

 </table>
 </div> <!-- grid-container -->
}

A few points of interest:

The Index method in the controller returns a ViewModel. By default, all configurable parameters (page size, time period, page number and log level) are not set, and all log messages are displayed with the default page size of 20 entries. When a value is set in the UI and the form is submitted, a corresponding parameter is passed to the controller.

public ActionResult Index(string Period = null, int? PageSize = null, int? page = null, string LogLevel = null)
{
 string defaultPeriod = Session["Period"] == null ? "All" : Session["Period"].ToString();
 string defaultLogLevel = Session["LogLevel"] == null ? "All" : Session["LogLevel"].ToString();

 LoggingIndexModel model = new LoggingIndexModel();

 model.Period = Period ?? defaultPeriod;
 model.LogLevel = LogLevel ?? defaultLogLevel;
 model.CurrentPageIndex = page.HasValue ? page.Value - 1 : 0;
 model.PageSize = PageSize.HasValue ? PageSize.Value : 20;

 TimePeriod timePeriod = TimePeriodHelper.GetUtcTimePeriod(model.Period);

 model.LogEvents = repository.GetByDateRangeAndType(model.CurrentPageIndex, model.PageSize, timePeriod.Start, timePeriod.End, model.LogLevel);

 ViewData["Period"] = model.Period;
 ViewData["LogLevel"] = model.LogLevel;
 ViewData["PageSize"] = model.PageSize;

 Session["Period"] = model.Period;
 Session["LogLevel"] = model.LogLevel;

 return View(model);
}

GetByDateRangeAndType does the work for selecting appropriate set of log messages from the database.

public IPagedList<LogEntry> GetByDateRangeAndType(int pageIndex, int pageSize, DateTime start, DateTime end, string logLevel)
{
 IQueryable<LogEntry> list;
 IPagedList<LogEntry> pagedList;

 list = db.LogEntries.Where(e =>
   (e.TimeStamp >= start && e.TimeStamp <= end));

 if (logLevel != LogTypeNames.All.ToString())
 {
  list = list.Where(e => e.LogType.Type.ToLower() == logLevel.ToLower());
 }

 list = list.OrderByDescending(e => e.TimeStamp);
 pagedList = new PagedList<LogEntry>(list, pageIndex, pageSize);
 return pagedList;
}

The data is returned in the form of a PagedList which is implemented as follows:

public interface IPagedList<T> : IList<T>
{
 int PageCount { get; }
 int TotalItemCount { get; }
 int PageIndex { get; }
 int PageNumber { get; }
 int PageSize { get; }

 bool HasPreviousPage { get; }
 bool HasNextPage { get; }
 bool IsFirstPage { get; }
 bool IsLastPage { get; }
}

Main part of the PagedList class:

public class PagedList<T> : List<T>, IPagedList<T>
{
 public PagedList(IEnumerable<T> source, int index, int pageSize)
  : this(source, index, pageSize, null)
 {
 }

 #region IPagedList Members

 public int PageCount { get; private set; }
 public int TotalItemCount { get; private set; }
 public int PageIndex { get; private set; }
 public int PageNumber { get { return PageIndex + 1; } }
 public int PageSize { get; private set; }
 public bool HasPreviousPage { get; private set; }
 public bool HasNextPage { get; private set; }
 public bool IsFirstPage { get; private set; }
 public bool IsLastPage { get; private set; }

 #endregion

 protected void Initialize(IQueryable<T> source, int index, int pageSize, int? totalCount)
 {
  //### argument checking
  if (index < 0)
  {
   throw new ArgumentOutOfRangeException("PageIndex cannot be below 0.");
  }
  if (pageSize < 1)
  {
   throw new ArgumentOutOfRangeException("PageSize cannot be less than 1.");
  }

  //### set source to blank list if source is null to prevent exceptions
  if (source == null)
  {
   source = new List<T>().AsQueryable();
  }

  //### set properties
  if (!totalCount.HasValue)
  {
   TotalItemCount = source.Count();
  }
  PageSize = pageSize;
  PageIndex = index;
  if (TotalItemCount > 0)
  {
   PageCount = (int)Math.Ceiling(TotalItemCount / (double)PageSize);
  }
  else
  {
   PageCount = 0;
  }
  HasPreviousPage = (PageIndex > 0);
  HasNextPage = (PageIndex < (PageCount - 1));
  IsFirstPage = (PageIndex <= 0);
  IsLastPage = (PageIndex >= (PageCount - 1));

  //### add items to internal list
  if (TotalItemCount > 0)
  {
   AddRange(source.Skip((index) * pageSize).Take(pageSize).ToList());
  }
 }
}

PagedList uses some helper methods from the Pager class to render HTML and generate links to other pages of the log.

public class Pager
{
 .....

 /// <summary>
 /// Rendes HTML to display a "pager" control (used at the top and bottom of the list of logged messages)
 /// </summary>
 /// <returns>String of HTML</returns>
 public string RenderHtml()
 {
  int pageCount = (int)Math.Ceiling(totalItemCount / (double)pageSize);
  const int nrOfPagesToDisplay = 10;

  var sb = new StringBuilder();

  // Previous
  if (currentPage > 1)
  {
   sb.Append(GeneratePageLink("<", this.currentPage - 1));
  }
  else
  {
   sb.Append("<span class=\"disabled\"><</span>");
  }

  int start = 1;
  int end = pageCount;

  if (pageCount > nrOfPagesToDisplay)
  {
   int middle = (int)Math.Ceiling(nrOfPagesToDisplay / 2d) - 1;
   int below = (currentPage - middle);
   int above = (currentPage + middle);

   if (below < 4)
   {
    above = nrOfPagesToDisplay;
    below = 1;
   }
   else if (above > (pageCount - 4))
   {
    above = pageCount;
    below = (pageCount - nrOfPagesToDisplay);
   }

   start = below;
   end = above;
  }

  if (start > 3)
  {
   sb.Append(GeneratePageLink("1", 1));
   sb.Append(GeneratePageLink("2", 2));
   sb.Append("...");
  }
  for (int i = start; i <= end; i++)
  {
   if (i == currentPage)
   {
    sb.AppendFormat("<span class=\"current\">{0}</span>", i);
   }
   else
   {
    sb.Append(GeneratePageLink(i.ToString(), i));
   }
  }
  if (end < (pageCount - 3))
  {
   sb.Append("...");
   sb.Append(GeneratePageLink((pageCount - 1).ToString(), pageCount - 1));
   sb.Append(GeneratePageLink(pageCount.ToString(), pageCount));
  }

  // Next
  if (currentPage < pageCount)
  {
   sb.Append(GeneratePageLink(">", (currentPage + 1)));
  }
  else
  {
   sb.Append("<span class=\"disabled\">></span>");
  }
  return sb.ToString();
 }

 /// <summary>
 /// Generates a link to a page
 /// </summary>
 /// <param name="linkText">Text displayed on the page</param>
 /// <param name="pageNumber">Number of the page the link leads to</param>
 /// <returns></returns>
 private string GeneratePageLink(string linkText, int pageNumber)
 {
  var pageLinkValueDictionary = new RouteValueDictionary(linkWithoutPageValuesDictionary) {{"page", pageNumber}};
  var virtualPathData = RouteTable.Routes.GetVirtualPath(this.viewContext.RequestContext, pageLinkValueDictionary);

  if (virtualPathData != null)
  {
   const string linkFormat = "<a href=\"{0}\">{1}</a>";
   return String.Format(linkFormat, virtualPathData.VirtualPath, linkText);
  }
  return null;
 }
}

Details view.

There is nothing special about the details view - it's a usual MVC view that displays entity data.

@model Recipes.Models.LogEntry
@{
    ViewBag.Title = "Details";
}

<link href="@Url.Content("~/Content/logging.css")" rel="stylesheet" type="text/css" />

<h2>Details</h2>

<p>        
    @Html.ActionLink("Back to List", "Index")
</p>

<fieldset>
    <legend>Fields</legend>
        
    <div class="display-label">Id</div>
    <div class="display-field">@Model.Id</div>
        
    <div class="display-label">LogDate</div>
    <div class="display-field">@String.Format("{0:g}", Model.TimeStamp)</div>
        
    <div class="display-label">Source</div>
    <div class="display-field">@Model.Source</div>
        
    <div class="display-label">Type</div>
    <div class="display-field">@Model.LogType.Type</div>
        
    <div class="display-label">Message</div>
    <div class="display-field">
        <pre>@Model.Message.WordWrap(80)</pre>
    </div>
        
    <div class="display-label">StackTrace</div>
    <div class="display-field">@Model.StackTrace</div>                      
        
</fieldset>

<p>        
    @Html.ActionLink("Back to List", "Index")
</p>

Details Controller

public ActionResult Details(string loggerProviderName, string id)
{
 LogEntry logEvent = repository.GetById(id);

 return View(logEvent);
}

The final result is represented in the image below:

MVC logging engine

References

Processing Unhandled Exceptions (C#)
Logging in MVC Part 1- Elmah (and other posts of the series)
MVC Basic Site: Step 2 - Exceptions Management
How is Error.cshtml called in ASP.NET MVC?
by . Also posted on my website

No comments: