Monday, October 31, 2011

Logging in MVC Part 3 – NLog

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:
01CREATE TABLE [dbo].[NLog_Error](
02    [Id] [int] IDENTITY(1,1) NOT NULL,
03    [time_stamp] [datetime] NOT NULL,
04    [host] [nvarchar](max) NOT NULL,
05    [type] [nvarchar](50) NOT NULL,
06    1 [nvarchar](50) NOT NULL,
07    [message] [nvarchar](max) NOT NULL,
08    [level] [nvarchar](50) NOT NULL,
09    [logger] [nvarchar](50) NOT NULL,
10    [stacktrace] [nvarchar](max) NOT NULL,
11    [allxml] [ntext] NOT NULL,
12 CONSTRAINT [PK_NLogError] PRIMARY KEY CLUSTERED
13(
14    [Id] ASC
15)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, IGNORE_DUP_KEY = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]
16) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]
17
18GO
19
20ALTER TABLE [dbo].[NLog_Error] ADD  CONSTRAINT [DF_NLogError_time_stamp]  DEFAULT (getdate()) FOR [time_stamp]
21GO

Configure our NLog configuration file

Create a file called NLog.config in the root directory of your website and paste the following into it:
01<?xml version="1.0" ?>
02<nlog autoReload="true" throwExceptions="true" internalLogFile="${basedir}/App_Data/nlog.txt" internalLogLevel="Debug"
03 internalLogToConsole="true">
04
05 <targets>
06 <!--Useful for debugging-->
07 <target name="consolelog" type="ColoredConsole"
08 layout="${date:format=HH\:mm\:ss}|${level}|${stacktrace}|${message}" />
09
10 <target name="filelog" type="File" fileName="${basedir}/App_Data/Site.log"
11 layout="${date}: ${message}" />
12
13 <target name="eventlog" type="EventLog" source="My App" log="Application"
14 layout="${date}: ${message} ${stacktrace}" />
15
16 <target name="databaselog" type="Database">
17
18 <dbProvider>sqlserver</dbProvider>
19
20 <!-- database connection parameters -->
21 <!-- alternatively you could provide a single 'connectionstring' parameter -->
22 <connectionString>Data Source=[Machine]\[Instance];Initial Catalog=[DatabaseName];Integrated Security=SSPI</connectionString>
23
24 <commandText>
25 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);
26 </commandText>
27
28 <parameter name="@time_stamp" layout="${utc_date}" />
29 <parameter name="@level" layout="${level}" />
30 <parameter name="@host" layout="${machinename}" />
31 <parameter name="@type" layout="${exception:format=type}" />
32 <parameter name="@source" layout="${callsite:className=true:fileName=false:includeSourcePath=false:methodName=false}" />
33 <parameter name="@logger" layout="${logger}" />
34 <parameter name="@message" layout="${message}" />
35 <parameter name="@stacktrace" layout="${exception:stacktrace}" />
36 <parameter name="@allxml" layout="${web_variables}" />
37
38 </target>
39
40 </targets>
41
42 <rules>
43 <!--
44 <logger name="*" minlevel="Fatal" writeTo="eventlog" />
45 -->
46 <logger name="*" minlevel="Info" writeTo="filelog" />
47 <logger name="*" minlevel="Info" writeTo="databaselog" />
48 </rules>
49
50</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’ :
01using System;
02using System.Collections.Generic;
03using System.Linq;
04using System.Web;
05
06namespace MySampleApp.Services.Logging
07{
08 public interface ILogger
09 {
10 void Info(string message);
11
12 void Warn(string message);
13
14 void Debug(string message);
15
16 void Error(string message);
17 void Error(string message, Exception x);
18 void Error(Exception x);
19
20 void Fatal(string message);
21 void Fatal(Exception x);
22
23 }
24}
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’:
01using System;
02using System.Collections.Generic;
03using System.Linq;
04using System.Web;
05
06namespace MySampleApp.Services.Logging
07{
08 public class LogUtility
09 {
10
11 public static string BuildExceptionMessage(Exception x)
12 {
13
14 Exception logException = x;
15 if (x.InnerException != null)
16 logException = x.InnerException;
17
18 string strErrorMsg = Environment.NewLine + "Error in Path :" + System.Web.HttpContext.Current.Request.Path;
19
20 // Get the QueryString along with the Virtual Path
21 strErrorMsg += Environment.NewLine + "Raw Url :" + System.Web.HttpContext.Current.Request.RawUrl;
22
23 // Get the error message
24 strErrorMsg += Environment.NewLine + "Message :" + logException.Message;
25
26 // Source of the message
27 strErrorMsg += Environment.NewLine + "Source :" + logException.Source;
28
29 // Stack Trace of the error
30
31 strErrorMsg += Environment.NewLine + "Stack Trace :" + logException.StackTrace;
32
33 // Method where the error occurred
34 strErrorMsg += Environment.NewLine + "TargetSite :" + logException.TargetSite;
35 return strErrorMsg;
36 }
37 }
38}
Next create a new folder under “Services -> Logging” called “NLog”.
Add the following code to a new file called, “NLogLogger.cs”:
01using System;
02using System.Collections.Generic;
03using System.Linq;
04using System.Web;
05
06using NLog;
07
08namespace MySampleApp.Services.Logging.NLog
09{
10 public class NLogLogger : ILogger
11 {
12
13 private Logger _logger;
14
15 public NLogLogger()
16 {
17 _logger = LogManager.GetCurrentClassLogger();
18 }
19
20 public void Info(string message)
21 {
22 _logger.Info(message);
23 }
24
25 public void Warn(string message)
26 {
27 _logger.Warn(message);
28 }
29
30 public void Debug(string message)
31 {
32 _logger.Debug(message);
33 }
34
35 public void Error(string message)
36 {
37 _logger.Error(message);
38 }
39
40 public void Error(Exception x)
41 {
42 Error(LogUtility.BuildExceptionMessage(x));
43 }
44
45 public void Error(string message, Exception x)
46 {
47 _logger.ErrorException(message, x);
48 }
49
50 public void Fatal(string message)
51 {
52 _logger.Fatal(message);
53 }
54
55 public void Fatal(Exception x)
56 {
57 Fatal(LogUtility.BuildExceptionMessage(x));
58 }
59 }
60}
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”:
01using System;
02using System.Collections.Generic;
03using System.Globalization;
04using System.Linq;
05using System.Text;
06using System.Web;
07
08using NLog;
09using NLog.Config;
10
11namespace MySampleApp.Services.Logging.NLog
12{
13 [LayoutRenderer("utc_date")]
14 public class UtcDateRenderer : LayoutRenderer
15 {
16
17 ///
18 /// Initializes a new instance of the  class.
19 ///
20 public UtcDateRenderer()
21 {
22 this.Format = "G";
23 this.Culture = CultureInfo.InvariantCulture;
24 }
25
26 protected override int GetEstimatedBufferSize(LogEventInfo ev)
27 {
28 // Dates can be 6, 8, 10 bytes so let's go with 10
29 return 10;
30 }
31
32 ///
33 /// Gets or sets the culture used for rendering.
34 ///
35 ///
36 public CultureInfo Culture { get; set; }
37
38 ///
39 /// Gets or sets the date format. Can be any argument accepted by DateTime.ToString(format).
40 ///
41 ///
42 [DefaultParameter]
43 public string Format { get; set; }
44
45 ///
46 /// Renders the current date and appends it to the specified .
47 ///
48 /// <param name="builder">The  to append the rendered data to.
49 /// <param name="logEvent">Logging event.
50 protected override void Append(StringBuilder builder, LogEventInfo logEvent)
51 {
52 builder.Append(logEvent.TimeStamp.ToUniversalTime().ToString(this.Format, this.Culture));
53 }
54
55 }
56}
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”:
001using System;
002using System.Collections.Generic;
003using System.Globalization;
004using System.Linq;
005using System.Text;
006using System.Web;
007
008using System.Xml;
009
010using NLog;
011using NLog.Config;
012
013namespace MySampleApp.Services.Logging.NLog
014{
015 [LayoutRenderer("web_variables")]
016 public class WebVariablesRenderer : LayoutRenderer
017 {
018
019 ///
020 /// Initializes a new instance of the  class.
021 ///
022 public WebVariablesRenderer()
023 {
024 this.Format = "";
025 this.Culture = CultureInfo.InvariantCulture;
026 }
027
028 protected override int GetEstimatedBufferSize(LogEventInfo ev)
029 {
030 // This will be XML of an unknown size
031 return 10000;
032 }
033
034 ///
035 /// Gets or sets the culture used for rendering.
036 ///
037 ///
038 public CultureInfo Culture { get; set; }
039
040 ///
041 /// Gets or sets the date format. Can be any argument accepted by DateTime.ToString(format).
042 ///
043 ///
044 [DefaultParameter]
045 public string Format { get; set; }
046
047 ///
048 /// Renders the current date and appends it to the specified .
049 ///
050 /// <param name="builder">The  to append the rendered data to.
051 /// <param name="logEvent">Logging event.
052 protected override void Append(StringBuilder builder, LogEventInfo logEvent)
053 {
054 StringBuilder sb = new StringBuilder();
055 XmlWriter writer = XmlWriter.Create(sb);
056
057 writer.WriteStartElement("error");
058
059 // -----------------------------------------
060 // Server Variables
061 // -----------------------------------------
062 writer.WriteStartElement("serverVariables");
063
064 foreach (string key in HttpContext.Current.Request.ServerVariables.AllKeys)
065 {
066 writer.WriteStartElement("item");
067 writer.WriteAttributeString("name", key);
068
069 writer.WriteStartElement("value");
070 writer.WriteAttributeString("string", HttpContext.Current.Request.ServerVariables[key].ToString());
071 writer.WriteEndElement();
072
073 writer.WriteEndElement();
074 }
075
076 writer.WriteEndElement();
077
078 // -----------------------------------------
079 // Cookies
080 // -----------------------------------------
081 writer.WriteStartElement("cookies");
082
083 foreach (string key in HttpContext.Current.Request.Cookies.AllKeys)
084 {
085 writer.WriteStartElement("item");
086 writer.WriteAttributeString("name", key);
087
088 writer.WriteStartElement("value");
089 writer.WriteAttributeString("string", HttpContext.Current.Request.Cookies[key].Value.ToString());
090 writer.WriteEndElement();
091
092 writer.WriteEndElement();
093 }
094
095 writer.WriteEndElement();
096 // -----------------------------------------
097
098 writer.WriteEndElement();
099 // -----------------------------------------
100
101 writer.Flush();
102 writer.Close();
103
104 string xml = sb.ToString();
105
106 builder.Append(xml);
107 }
108
109 }
110}
The last step is to modify the global.asax.cs file so that NLog is aware of the new layout renderers:
01protected void Application_Start()
02 {
03 AreaRegistration.RegisterAllAreas();
04
05 RegisterRoutes(RouteTable.Routes);
06
07 ControllerBuilder.Current.SetControllerFactory(new ErrorHandlingControllerFactory());
08
09 // Register custom NLog Layout renderers
10 LayoutRendererFactory.AddLayoutRenderer("utc_date", typeof(MySampleApp.Services.Logging.NLog.UtcDateRenderer));
11 LayoutRendererFactory.AddLayoutRenderer("web_variables", typeof(MySampleApp.Services.Logging.NLog.WebVariablesRenderer));
12
13 }
141</pre>
15At this point we are all set up to log our own messages using NLog.
16
17To test NLog out, add some code to one of your controllers like this:
18
191
20public ActionResult Index()
21 {
22 IEnumerable list = activityRepository.GetAll();
23
24 NLogLogger logger = new NLogLogger();
25 logger.Info("We're on the Index page for Activities");
26
27 try
28 {
29 throw new Exception("A test exception");
30 }
31 catch(Exception ex)
32 {
33 logger.Error("An error has occurred", ex);
34 }
35
36 return View(list);
37 }

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.

1 comment:

darichkid said...

This is even better than NLog:
http://www.kellermansoftware.com/p-14-net-logging-library.aspx

April 11, 2013 at 3:07 PM

Post a Comment

Subscribe to: Post Comments (Atom)
Twitter Bird Gadget