Trace Activities with NLog

Today’s post is dedicated to NLog – one of the logging libraries available for .NET developers. NLog has a lot of features and options, but also might seem complicated on first sight. Checking the examples should usually allay your fears but it will still take you some time to get along with NLog’s syntax and configuration. I will try to make the learning curve less steep by providing you with configuration options that are currently working in my projects. If you are new to NLog, I recommend you have a look at its tutorial before reading on.

I usually add NLog configuration to my web/app.config file so therefore I need to define the nlog section at the beginning of the configuration file:

<?xml version="1.0"?>
<configuration>
  <configSections>
    <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog"/>
  </configSections>
  ...
</configuration>

Our section is set up so we are ready to configure our loggers. But before we do that, I would like to show you two NLog extensions that I use.

Extending NLog to Your Needs

Grouping Logs by the Trace Correlation Activity ID

System.Diagnostics.Trace provides great functionality that allows you to group your logs by an activity ID. This ID is valid only in its code scope and might help you find logs that are connected with a particular logging event. I describe activity IDs and their usage some time ago in the following post: Grouping application traces using ActivityId (System.Diagnostics). There is no built-in way to render activity traces using NLog, but fortunately it’s not a big deal to extend it with such a functionality. For this purpose, we will create a new TraceActivityIdLayoutRenderer class:

namespace LowLevelDesign.NLog.LayoutRenderers
{
    /// <summary>
    /// The trace correlation activity id.
    /// </summary>
    [LayoutRenderer("activityid")]
    [ThreadAgnostic]
    public class TraceActivityIdLayoutRenderer : LayoutRenderer
    {
        /// <summary>
        /// Renders the current trace activity ID.
        /// </summary>
        /// <param name="builder">The <see cref="
        /// StringBuilder"/> to append the rendered data to.</param>
        /// <param name="logEvent">Logging event.</param>
        protected override void Append(StringBuilder builder, LogEventInfo logEvent)
        {
            builder.Append(Trace.CorrelationManager.ActivityId.ToString
            ("D", CultureInfo.InvariantCulture));
        }
    }
}

To properly save activity transfers from .NET sources, we also need to forward System.Diagnostics traces to NLog loggers. There is already a built-in NLogTraceListener class, but unfortunately it does not save the relatedActivityId value. We will slightly modify it so the relatedActivityId will become one of the event properties:

using System;
using System.Diagnostics;
using System.Reflection;
using NLog;

namespace LowLevelDesign.NLog 
{
    public class NLogTraceListener : global::NLog.NLogTraceListener
    {
        private static readonly Assembly systemAssembly = typeof(Trace).Assembly;
    
        public override void TraceTransfer(TraceEventCache eventCache, 
        string loggerName, int eventId, string message, Guid relatedActivityId)
        {
           var ev = new LogEventInfo();

            ev.LoggerName = (loggerName ?? this.Name) ?? string.Empty;
            
#if !NET_CF
            if (this.AutoLoggerName)
            {
                var stack = new StackTrace();
                int userFrameIndex = -1;
                MethodBase userMethod = null;

                for (int i = 0; i < stack.FrameCount; ++i)
                {
                    var frame = stack.GetFrame(i);
                    var method = frame.GetMethod();

                    if (method.DeclaringType == this.GetType())
                    {
                        // skip all methods of this type
                        continue;
                    }

                    if (method.DeclaringType.Assembly == systemAssembly)
                    {
                        // skip all methods from System.dll
                        continue;
                    }

                    userFrameIndex = i;
                    userMethod = method;
                    break;
                }

                if (userFrameIndex >= 0)
                {
                    ev.SetStackTrace(stack, userFrameIndex);
                    if (userMethod.DeclaringType != null)
                    {
                        ev.LoggerName = userMethod.DeclaringType.FullName;
                    }
                }
            }
#endif

            ev.TimeStamp = DateTime.Now;
            ev.Message = message;
            ev.Level = this.ForceLogLevel ?? LogLevel.Debug;

            ev.Properties.Add("EventID", eventId);
            ev.Properties.Add("RelatedActivityID", relatedActivityId);

            Logger logger = LogManager.GetLogger(ev.LoggerName);
            logger.Log(ev);
        }
    }
}

Later on, I will show you how to plug the NLogTraceAppender and use the above layout renderer in the target’s layout.

Saving Logs to a MySQL Database

The next thing I missed in NLog was a possibility to save the logs to a MySql database – although it is very easy to configure the database target to do it. Firstly, let’s create a partitioned table for our logs:

create table LogTable
(
    sequence_id int not null auto_increment,
    machine_name varchar(50) not null,
    process_id int not null,
    thread_id int not null,
    time_stamp datetime not null,
    level varchar(5) not null,
    logger varchar(80) not null,
    activity_id char(36) null,
    related_activity_id CHAR(36) null,
    message varchar(400) not null,
    exception varchar(4000) null,
    primary key (sequence_id, time_stamp)
) engine=InnoDB
partition by range columns(time_stamp)
(partition p20121026 values less than ('2012-10-27 00:00'),
 partition p20121027 values less than ('2012-10-28 00:00'),
 partition p20121028 values less than ('2012-10-29 00:00'));

Next, we need to download MySql.Data assembly (for instance from Nuget) and add the MySql provider and our connection string to the app/web.config:

<configuration>
...
  <system.data>
    <DbProviderFactories>
      <add name="MySql Data Provider" 
      invariant="System.Data.MySqlClient" 
            type="MySql.Data.MySqlClient.MySqlClientFactory, 
            MySql.Data" description="MySql data provider" />
    </DbProviderFactories>
  </system.data>
  <connectionStrings>
    <add name="MySqlTraceConnString" 
      connectionString="Data Source=localhost;
      Initial Catalog=DiagnosticsDB;User Id=test;Password=test;" 
      providerName="System.Data.MySqlClient" />
  </connectionStrings>
  ...
</configuration>

In order to use the created table for our logs, we need to configure the NLog’s database target. We will do it in the following sections.

Configuring NLog

Debug NLog Configuration

Usually while running the debug-version of the application, we are interested in the most verbose logs. Additionally, our logs should be easily accessible, readable and easy to remove. The best options for log output would be probably either a console, a file or some trace output. The log message should also contain as much information as possible, including process ID, thread ID maybe even some environment variables. As mentioned previously, we will also collect traces from System.Diagnostics.TraceSource (let’s call it TestSource) and forward them to the NLog logger. An example of the NLog debug configuration for a console application might look as follows:

<system.diagnostics>
  <trace autoflush="true" />
  <sources>
    <source name="TestSource" switchValue="All">
      <listeners>
        <add name="nlog" />
      </listeners>
    </source>
  </sources>
  <sharedListeners>
    <add name="nlog" type="
    LowLevelDesign.NLog.NLogTraceListener, LowLevelDesign.NLog.Ext" />
  </sharedListeners>
</system.diagnostics>

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" 
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <extensions>
    <add prefix="lld" assembly="LowLevelDesign.NLog.Ext" />
  </extensions>
  <targets>
    <target name="console" xsi:type="ColoredConsole" 
      layout="${longdate}|${event-context:item=RelatedActivityID}-&gt;${lld.activityid}|
        ${processid}(${threadid})|${logger}|${uppercase:${level}}|${message}
        ${onexception:|Exception occurred\:${exception:format=tostring}}" />
    <target name="file" xsi:type="File" 
      fileName="c:\logs\test.log" deleteOldFileOnStartup="true" 
      layout="${longdate}|${event-context:item=RelatedActivityID}-&gt;
        ${lld.activityid}|${processid}(${threadid})|${logger}|${uppercase:${level}}|
        ${message}${onexception:|Exception occurred\:${exception:format=tostring}}" />
  </targets>
  <rules>
    <logger name="TestLogger.*" minlevel="Debug" writeTo="console" />
    <logger name="TestLogger.*" minlevel="Debug" writeTo="file" />
    <logger name="TestSource.*" minlevel="Debug" writeTo="console" />
    <logger name="TestSource.*" minlevel="Debug" writeTo="file" />
  </rules>
</nlog>

For ASP.NET applications, we will also be interested in some web-specific information, such as a request URL, session or application variables, etc. With NLog, it just requires adding one of the aspnet-... layout renderers to the layout attribute (a list of all built-in layout renderers can be found here).

Release NLog Configuration

The logging configuration for a production environment (release) is slightly different. Our application should be by now tested and we don’t want to fill up the server’s disk space with DEBUG logs. Also, we usually want our targets to be more reliable and easy to monitor. I consider the system event log to be a good target for INFO (and up) logs and a database to be a great place to store ERROR and FATAL logs. An example configuration might look as follows (again, we are forwarding messages from System.Diagnostics.TraceSource to NLog):

<system.diagnostics>
  <trace autoflush="true" />
  <sources>
    <source name="TestSource" switchValue="Error">
      <listeners>
        <add name="nlog" />
      </listeners>
    </source>
  </sources>
  <sharedListeners>
    <add name="nlog" 
    type="LowLevelDesign.NLog.NLogTraceListener, LowLevelDesign.NLog.Ext" />
  </sharedListeners>
</system.diagnostics>

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" 
        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <extensions>
    <add prefix="lld" assembly="LowLevelDesign.NLog.Ext" />
  </extensions>
  <targets>
    <target name="database" xsi:type="Database">
      <connectionStringName>MySqlTraceConnString</connectionStringName>
      
      <commandText>
          insert into LogTable(machine_name, process_id, thread_id, time_stamp, level, logger, 
            activity_id, related_activity_id,  
            message, exception) values (@machine_name, @process_id, @thread_id, 
              @time_stamp, @level, @logger, 
              @activity_id, @related_activity_id,  @message, @exception);
      </commandText>
      
      <parameter name="@machine_name" layout="${machinename}" />
      <parameter name="@process_id" layout="${processid}" />
      <parameter name="@thread_id" layout="${threadid}" />
      <parameter name="@time_stamp" layout="${longdate}" />
      <parameter name="@level" layout="${uppercase:${level}}" />
      <parameter name="@logger" layout="${logger}" />
      <parameter name="@activity_id" layout="${lld.activityid}" />
      <parameter name="@related_activity_id" 
      layout="${event-context:item=RelatedActivityID}" />
      <parameter name="@message" layout="${message}" />
      <parameter name="@exception" layout="${exception:format=tostring" />
    </target>
    
    <target name="eventlog" xsi:type="eventlog" log="Application" 
       source="NLog" 
       layout="${lld.activityid}|${logger}|${uppercase:${level}}|${message}
         ${onexception:|Exception occurred\:${exception:format=tostring}}" />
  </targets>
  <rules>
    <logger name="TestLogger" minlevel="Info" writeTo="eventlog" />
    <logger name="TestLogger" minlevel="Error" writeTo="database" />
    <logger name="TestSource" minlevel="Info" writeTo="eventlog" />
    <logger name="TestSource" minlevel="Error" writeTo="database" />
  </rules>
</nlog>

If our logs need to contain some ASP.NET specific information, we can add aspnet layout renderers to the logger layouts.

Conclusion

I hope the presented examples of NLog configurations will help you create your own set of logger layouts and targets that will best suit your needs. NLog has a lot of features and I advise you to have a look at its wiki and source code in order to know it better. Some hidden gems include: logging to performance counters and reading performance counters values; logging to a web service; rendering your logs in a form of XML, JSON or CSV; log installers (for eventlogs or performance counters) and many more. As usual, the code presented in this post is available for download on my CodePlex page.