Logging in MVC Part 3 – NLog

This is part 3 of the MVC Logging series. Other articles in the series are:

Introduction

In the previous article we implemented Health Monitoring into our MVC website.

Now we need to provide a way to log our own custom messages so that we can keep track of important events that occur throughout our website.

For example, you may need to log information before and after a financial transaction has occurred on your eCommerce website.

It is easy to write your own logger but as there are already many established logging frameworks already available for .NET I’ve decided to concentrate on 2 of the most popular ones: Log4Net and NLog.

In this article we will concentrate on setting up NLog and in the next article we will take a look at Log4Net.

NLog

Prior to working on this series I had never ever used NLog - I’ve always used Log4Net. However, after spending some time on Rob Connerys blog and looking at his MVC Storefront series and his MVC starter kit I decided to look at NLog so that I have another logging framework in my utility belt. It’s always good to broaden your knowledge and learn a new skill or master a new toolkit.

So what follows is pretty much exactly what Rob Conery did for his MVC starter kit website. However I have extended the default NLog functionality by including 2 new layout renderers.

Here are the steps we need to take to integrate NLog into our website:

1. Download NLog.

2. Create a table in our database to store the NLog messages.

3. Configure our NLog configuration file.

4. Set up a logging interface for our website.

5. Implement an NLog logger that uses our interface to log messages to the database table in step 2.

6. Add some additional layout renders that we will need for NLog.

Let’s tackle each one in order.

Download NLog

1. Go to http://nlog-project.org/ and download NLog.

2. Add a reference to the NLog binary in your website

Create a table in our database to store the NLog messages

NLog is very flexible and it is up to you as to what information you want to store in the database but for our sample website we will be using the script below.

1. Run the following script against your database:

CREATE TABLE [dbo].[NLog_Error](
	[Id] [int] IDENTITY(1,1) NOT NULL,
	[time_stamp] [datetime] NOT NULL,
	[host] [nvarchar](max) NOT NULL,
	[type] [nvarchar](50) NOT NULL,
	1 [nvarchar](50) NOT NULL,
	[message] [nvarchar](max) NOT NULL,
	[level] [nvarchar](50) NOT NULL,
	[logger] [nvarchar](50) NOT NULL,
	[stacktrace] [nvarchar](max) NOT NULL,
	[allxml] [ntext] NOT NULL,
 CONSTRAINT [PK_NLogError] PRIMARY KEY CLUSTERED
(
	[Id] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]
) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]

GO

ALTER TABLE [dbo].[NLog_Error] ADD  CONSTRAINT [DF_NLogError_time_stamp]  DEFAULT (getdate()) FOR [time_stamp]
GO

Configure our NLog configuration file

Create a file called NLog.config in the root directory of your website and paste the following into it:

<?xml version="1.0" ?>
<nlog autoReload="true" throwExceptions="true" internalLogFile="${basedir}/App_Data/nlog.txt" internalLogLevel="Debug"
 internalLogToConsole="true">

 <targets>
 <!--Useful for debugging-->
 <target name="consolelog" type="ColoredConsole"
 layout="${date:format=HH\:mm\:ss}|${level}|${stacktrace}|${message}" />

 <target name="filelog" type="File" fileName="${basedir}/App_Data/Site.log"
 layout="${date}: ${message}" />

 <target name="eventlog" type="EventLog" source="My App" log="Application"
 layout="${date}: ${message} ${stacktrace}" />

 <target name="databaselog" type="Database">

 <dbProvider>sqlserver</dbProvider>

 <!-- database connection parameters -->
 <!-- alternatively you could provide a single 'connectionstring' parameter -->
 <connectionString>Data Source=[Machine]\[Instance];Initial Catalog=[DatabaseName];Integrated Security=SSPI</connectionString>

 <commandText>
 insert into NLog_Error ([time_stamp],[level],[host],[type],1,[logger],[message],[stacktrace],[allxml]) values(@time_stamp,@level,@host,@type,@source,@logger,@message,@stacktrace,@allxml);
 </commandText>

 <parameter name="@time_stamp" layout="${utc_date}" />
 <parameter name="@level" layout="${level}" />
 <parameter name="@host" layout="${machinename}" />
 <parameter name="@type" layout="${exception:format=type}" />
 <parameter name="@source" layout="${callsite:className=true:fileName=false:includeSourcePath=false:methodName=false}" />
 <parameter name="@logger" layout="${logger}" />
 <parameter name="@message" layout="${message}" />
 <parameter name="@stacktrace" layout="${exception:stacktrace}" />
 <parameter name="@allxml" layout="${web_variables}" />

 </target>

 </targets>

 <rules>
 <!--
 <logger name="*" minlevel="Fatal" writeTo="eventlog" />
 -->
 <logger name="*" minlevel="Info" writeTo="filelog" />
 <logger name="*" minlevel="Info" writeTo="databaselog" />
 </rules>

</nlog>

The following link provides a handy reference to all of the layouts used by NLog:
http://nlog-project.org/wiki/Layout_renderers

You may notice that there are a couple of non-standard layouts used in the example above : {utc_date} and {web_variables}. But don’t worry we will come back to them later on in this article.

Set up a logging interface for our website

I’m just going to use the logging interface created by Rob Conery (although I noticed that the Orchard project has a fuller logging interface, but I think the one below is fine for most needs):

Before we add it in, let’s create a folder called ‘Services’ in the root directory of our website and a child folder in there called ‘Logging’.

Now, in the ‘Services -> Logging’ folder add the following code to a new file called, ‘ILogger.cs’ :

using System;
using System.Collections.Generic;
using System.Linq;
using System.Web;

namespace MySampleApp.Services.Logging
{
 public interface ILogger
 {
 void Info(string message);

 void Warn(string message);

 void Debug(string message);

 void Error(string message);
 void Error(string message, Exception x);
 void Error(Exception x);

 void Fatal(string message);
 void Fatal(Exception x);

 }
}

As per what Rob did, we will also add a helper function that will be used to format an exception. Place this in a file called, ‘LogUtility.cs’:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Web;

namespace MySampleApp.Services.Logging
{
 public class LogUtility
 {

 public static string BuildExceptionMessage(Exception x)
 {

 Exception logException = x;
 if (x.InnerException != null)
 logException = x.InnerException;

 string strErrorMsg = Environment.NewLine + "Error in Path :" + System.Web.HttpContext.Current.Request.Path;

 // Get the QueryString along with the Virtual Path
 strErrorMsg += Environment.NewLine + "Raw Url :" + System.Web.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;
 }
 }
}

Next create a new folder under “Services -> Logging” called “NLog”.

Add the following code to a new file called, “NLogLogger.cs”:

using System;
using System.Collections.Generic;
using System.Linq;
using System.Web;

using NLog;

namespace MySampleApp.Services.Logging.NLog
{
 public class NLogLogger : ILogger
 {

 private Logger _logger;

 public NLogLogger()
 {
 _logger = LogManager.GetCurrentClassLogger();
 }

 public void Info(string message)
 {
 _logger.Info(message);
 }

 public void Warn(string message)
 {
 _logger.Warn(message);
 }

 public void Debug(string message)
 {
 _logger.Debug(message);
 }

 public void Error(string message)
 {
 _logger.Error(message);
 }

 public void Error(Exception x)
 {
 Error(LogUtility.BuildExceptionMessage(x));
 }

 public void Error(string message, Exception x)
 {
 _logger.ErrorException(message, x);
 }

 public void Fatal(string message)
 {
 _logger.Fatal(message);
 }

 public void Fatal(Exception x)
 {
 Fatal(LogUtility.BuildExceptionMessage(x));
 }
 }
}

By default, NLog can only log the datetime using local time. However, in this series we need to integrate the NLog logs with Elmah and Health Monitoring which are all capable of storing their dates in UTC format. So to do that in NLog we need to create a new layout renderer.

In our NLog folder, add the following code to a new file called, “UtcDateRenderer.cs”:

using System;
using System.Collections.Generic;
using System.Globalization;
using System.Linq;
using System.Text;
using System.Web;

using NLog;
using NLog.Config;

namespace MySampleApp.Services.Logging.NLog
{
 [LayoutRenderer("utc_date")]
 public class UtcDateRenderer : LayoutRenderer
 {

 ///
 /// Initializes a new instance of the  class.
 ///
 public UtcDateRenderer()
 {
 this.Format = "G";
 this.Culture = CultureInfo.InvariantCulture;
 }

 protected override int GetEstimatedBufferSize(LogEventInfo ev)
 {
 // Dates can be 6, 8, 10 bytes so let's go with 10
 return 10;
 }

 ///
 /// Gets or sets the culture used for rendering.
 ///
 ///
 public CultureInfo Culture { get; set; }

 ///
 /// Gets or sets the date format. Can be any argument accepted by DateTime.ToString(format).
 ///
 ///
 [DefaultParameter]
 public string Format { get; set; }

 ///
 /// Renders the current date and appends it to the specified .
 ///
 /// <param name="builder">The  to append the rendered data to.
 /// <param name="logEvent">Logging event.
 protected override void Append(StringBuilder builder, LogEventInfo logEvent)
 {
 builder.Append(logEvent.TimeStamp.ToUniversalTime().ToString(this.Format, this.Culture));
 }

 }
}

Also, I like how ELMAH stores all of the web request and cookies information so let’s create another custom NLog renderer that will allow us to easily record all of this information.

Add the following code to a new file in the “NLog” folder, called “WebVariablesRenderer.cs”:

using System;
using System.Collections.Generic;
using System.Globalization;
using System.Linq;
using System.Text;
using System.Web;

using System.Xml;

using NLog;
using NLog.Config;

namespace MySampleApp.Services.Logging.NLog
{
 [LayoutRenderer("web_variables")]
 public class WebVariablesRenderer : LayoutRenderer
 {

 ///
 /// Initializes a new instance of the  class.
 ///
 public WebVariablesRenderer()
 {
 this.Format = "";
 this.Culture = CultureInfo.InvariantCulture;
 }

 protected override int GetEstimatedBufferSize(LogEventInfo ev)
 {
 // This will be XML of an unknown size
 return 10000;
 }

 ///
 /// Gets or sets the culture used for rendering.
 ///
 ///
 public CultureInfo Culture { get; set; }

 ///
 /// Gets or sets the date format. Can be any argument accepted by DateTime.ToString(format).
 ///
 ///
 [DefaultParameter]
 public string Format { get; set; }

 ///
 /// Renders the current date and appends it to the specified .
 ///
 /// <param name="builder">The  to append the rendered data to.
 /// <param name="logEvent">Logging event.
 protected override void Append(StringBuilder builder, LogEventInfo logEvent)
 {
 StringBuilder sb = new StringBuilder();
 XmlWriter writer = XmlWriter.Create(sb);

 writer.WriteStartElement("error");

 // -----------------------------------------
 // Server Variables
 // -----------------------------------------
 writer.WriteStartElement("serverVariables");

 foreach (string key in HttpContext.Current.Request.ServerVariables.AllKeys)
 {
 writer.WriteStartElement("item");
 writer.WriteAttributeString("name", key);

 writer.WriteStartElement("value");
 writer.WriteAttributeString("string", HttpContext.Current.Request.ServerVariables[key].ToString());
 writer.WriteEndElement();

 writer.WriteEndElement();
 }

 writer.WriteEndElement();

 // -----------------------------------------
 // Cookies
 // -----------------------------------------
 writer.WriteStartElement("cookies");

 foreach (string key in HttpContext.Current.Request.Cookies.AllKeys)
 {
 writer.WriteStartElement("item");
 writer.WriteAttributeString("name", key);

 writer.WriteStartElement("value");
 writer.WriteAttributeString("string", HttpContext.Current.Request.Cookies[key].Value.ToString());
 writer.WriteEndElement();

 writer.WriteEndElement();
 }

 writer.WriteEndElement();
 // -----------------------------------------

 writer.WriteEndElement();
 // -----------------------------------------

 writer.Flush();
 writer.Close();

 string xml = sb.ToString();

 builder.Append(xml);
 }

 }
}

The last step is to modify the global.asax.cs file so that NLog is aware of the new layout renderers:

protected void Application_Start()
 {
 AreaRegistration.RegisterAllAreas();

 RegisterRoutes(RouteTable.Routes);

 ControllerBuilder.Current.SetControllerFactory(new ErrorHandlingControllerFactory());

 // Register custom NLog Layout renderers
 LayoutRendererFactory.AddLayoutRenderer("utc_date", typeof(MySampleApp.Services.Logging.NLog.UtcDateRenderer));
 LayoutRendererFactory.AddLayoutRenderer("web_variables", typeof(MySampleApp.Services.Logging.NLog.WebVariablesRenderer));

 }
1</pre>
At this point we are all set up to log our own messages using NLog.

To test NLog out, add some code to one of your controllers like this:

1
public ActionResult Index()
 {
 IEnumerable list = activityRepository.GetAll();

 NLogLogger logger = new NLogLogger();
 logger.Info("We're on the Index page for Activities");

 try
 {
 throw new Exception("A test exception");
 }
 catch(Exception ex)
 {
 logger.Error("An error has occurred", ex);
 }

 return View(list);
 }

Conclusion

To recap, we now have the following in our MVC website:

* Elmah logging unhandled exceptions into the ‘ELMAH_Error’ table in our database.

* ASP.NET Health monitoring logging events to the ‘aspnet_WebEvent_Events’ table in our database.

* NLog logging messages and/or exceptions to the ‘NLog_Error’ table in our database.

I’ve purposefully let each one of these tools log messages to their own tables so that we can swap any of them out without affecting the other ones.

In the upcoming articles we will tie them all together and create a nice looking reporting tool that will consolidate all of the information that we are now logging on our website.

But before we do that in the next article we will quickly add Log4Net support to our website.

Download

The source code for part 3 is on the Downloads tab of the associate CodePlex website

About these ads
Tagged with: , , , ,
Posted in ASP.NET MVC
One comment on “Logging in MVC Part 3 – NLog
  1. SJ Clark says:

    For later versions of NLog (including v4.0.30319):
    In Global.asax.cs – Application_Start()
    Replace:
    LayoutRendererFactory.AddLayoutRenderer(“utc_date”, typeof(DevilfishSoftware.Services.Logging.NLog.UtcDateRenderer));
    LayoutRendererFactory.AddLayoutRenderer(“web_variables”, typeof(DevilfishSoftware.Services.Logging.NLog.WebVariablesRenderer));

    With:
    ConfigurationItemFactory.Default.LayoutRenderers.RegisterDefinition(“utc_date”, typeof(DevilfishSoftware.Services.Logging.NLog.UtcDateRenderer));
    ConfigurationItemFactory.Default.LayoutRenderers.RegisterDefinition(“utc_date”, typeof(DevilfishSoftware.Services.Logging.NLog.WebVariablesRenderer));

    LayoutRendererFactory is not recognized – duplicated.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

%d bloggers like this: