Introduction to tracing applications with NLog

Author: Jarosław Kowalski <jaak@jkowalski.net>

Once upon a time, when there were no debuggers in the world and software was mostly console-based, programmers used to output tracing messages using printf() statements. Today's world has seen huge advancement in technology and printf() was replaced with Console.WriteLine()...

We've all written code similiar to the following:

static void Main() 
{ 
    Console.WriteLine("SuperApp started."); 
    DoSomething();          
    Console.WriteLine("SuperApp finished."); 
}

Console.WriteLine() statements in the above example are called "tracing statements" because they are only used to report our application's control flow and have no other function. The output of Console.WriteLine() is called the program trace. In this example, the tracing statements produce output that tells us if the DoSomething() method has finished execution or not.

After giving the application some testing, we tend to remove the tracing code in order to improve performance (tracing can take a lot of time). Tracing instructions are usually commented out so that they can be re-enabled in the future. Unfortunately this requires our program to be recompiled.

Some time later, after removing hundreds of the comments and putting them back for the Nth time, we get the feeling that our tracing solution is not perfect and we could benefit from:

• the ability to control the level of detail of our trace messages (such as displaying only warnings and errors or very detailed program trace),
• the possibility of turning the tracing on and off for components of our proram separately, without turning the application off and recompiling it,
• writing trace messages to the file, system log, message queue or other output,
• being able to send particularly important messages by email or store them in a database,
• and others...

It may seem, that in the age of graphical debuggers, the usefulness of tracing-based solutions is limited. Sometimes tracing turns out to be the only tool available, which can be used to locate bug in a mission-critical system that cannot be switched off for a single minute.

What is NLog?

NLog (http://www.nlog-project.org) is a .NET library, which enables you to add sophisticated tracing code to your application, delivering the functionality mentioned above and much, much more.

NLog lets you write rules which control the flow of diagnostic traces from their sources to targets, which could be:

• a file
• text console
• email message
• database
• other machine on the network (using TCP/UDP)
• MSMQ-based message queue
• Event Log
• and others, described in http://www.nlog-project.org/targets.html

In addition, each tracing message can be augmented with pieces of contextual information, which will be sent with it to the target. The contextual information can include:

• current date and time (in various formats)
• log level
• soure name
• stack trace/information about the method that emitted the tracing message
• values of environment variables
• information about exceptions
• machine, process and thread names
• and many more, as described in http://www.nlog-project.org/layoutrenderers.html

Each tracing message is associated with a log level which describes its severity. NLog supports the following levels.

• Trace - Very detailed log messages, potentially of a high frequency and volume
• Debug -Less detailed and/or less frequent debugging messages
• Info - Informational messages
• Warn - Warnings which don't appear to the user of the application
• Error - Error messages
• Fatal - Fatal error messages. After a fatal error the application usually terminates.

NLog is a open source library distributed at no cost under the terms of BSD license, which permits commercial usage with almost no obligation. You can download NLog binary and source code releases from http://www.nlog-project.org/download.html. Graphical installer is also provided, which lets you install NLog in a preferred place and enable integration with Visual Studio 2005 (Express editions are also supported), including:

• configuration file templates
• Intellisense for NLog config files
• code snippets
• Add Reference... dialog integration

Our first NLog-enabled application

Let's create our first application that uses NLog using Visual Studio 2005. We'll start with a simple example that only logs to the console, and we'll be adding features that demonstrate how easy it is to control logging configuration in NLog.

The first step is to create a Visual Studio project (in this example we'll be using C#) and add NLog configuration file using "Add New Item..." dialog. Let's add an "Empty NLog Configuration File" and save it as "NLog.config":

Notice how a reference to NLog.dll has automatically been added to our project. The contents of NLog.config file, which we'll be modifying in this tutorial, are:

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" 
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"> 
  <targets> 
  </targets> 
  <rules> 
  </rules> 
</nlog> 

You only need to do one more thing: Change "Copy To Output Directory" option for this file to "Copy always". This way our configuration file will be placed in the same directory as the *.exe file and NLog will be able to pick it up without any special configuration.

It's time to configure log output. In the <targets /> section we'll add a entry that defines console output and the required output layout:

<targets> 
  <target name="console" xsi:type="Console" 
          layout="${longdate}|${level}|${message}"/> 
</targets> 

Notice how Visual Studio suggests the possible XML element names and attribute names/values. Once we type xsi:, we get a list of available log targets.

In the <rules /> section we'll add a rule that routes all message whose level is Debug or higher to the console. The XML is quite self-explanatory.

<rules> 
  <logger name="*" minlevel="Debug" writeTo="console"/> 
</rules> 

In order to send a diagnostic message, we use a Logger object, whose methods are named after supported log levels (Debug(), Info(), Fatal() and so on). Logger objects can be created thanks to the LogManager class. It's recommended that logger names correspond to the full class names in the application. The LogManager object has a GetCurrentClassLogger() method that automatically creates a logger based on the class its being called from.

Let's modify the wizard-generated C# file by adding "using NLog" statement at the beginning, the code to create logger and example log message. Note that you can quickly type the logger-creation statement by using the Code Snippet which is installed with NLog. Just type "nlogger" and press TAB twice.

using System; 
using System.Collections.Generic; 
using System.Text; 
using NLog; 
 
namespace NLogExample 
{ 
    class Program 
    { 
        private static Logger logger = LogManager.GetCurrentClassLogger(); 
         
        static void Main(string[] args) 
        { 
            logger.Debug("Hello World!"); 
        } 
    } 
}

The result of running this program is a message written to the console which includes the current date, log level (Debug) and the Hello World message.

Let's see how we achieved this:

1. LogManager.GetCurrentClassLogger(); creates an instance of Logger class which represents the source of log messages which is associated with current class.
2. Calling the Debug() method on the source object sends the diagnostic message on the Debug level.
3. Because our log level and source name match the rule defined in <rules /> section, the message gets formatted according to the "layout" specification and sent to the console.

More advanced logging scenario

Let's record our log messages, along with some contextual information such as the the current stack trace, to both a file and the console. To do this we need to defined another of type "File" and tell the node that we want write to it.

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" 
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"> 
  <targets> 
    <target name="console" xsi:type="ColoredConsole" 
            layout="${date:format=HH\:mm\:ss}|${level}|${stacktrace}|${message}"/> 
    <target name="file" xsi:type="File" fileName="${basedir}/file.txt" 
            layout="${stacktrace} ${message}"/> 
  </targets> 
  <rules> 
    <logger name="*" minlevel="Trace" writeTo="console,file"/> 
  </rules> 
</nlog> 

Here's the C# source code that emits some more log messages, additional methods are introduced here to observe the stack trace feature.

static void C() 
{ 
    logger.Info("Info CCC"); 
} 
static void B() 
{ 
    logger.Trace("Trace BBB"); 
    logger.Debug("Debug BBB"); 
    logger.Info("Info BBB"); 
    C(); 
    logger.Warn("Warn BBB"); 
    logger.Error("Error BBB"); 
    logger.Fatal("Fatal BBB"); 
} 
static void A() 
{ 
    logger.Trace("Trace AAA"); 
    logger.Debug("Debug AAA"); 
    logger.Info("Info AAA"); 
    B(); 
    logger.Warn("Warn AAA"); 
    logger.Error("Error AAA"); 
    logger.Fatal("Fatal AAA"); 
} 
static void Main(string[] args) 
{ 
    logger.Trace("This is a Trace message"); 
    logger.Debug("This is a Debug message"); 
    logger.Info("This is an Info message"); 
    A(); 
    logger.Warn("This is a Warn message"); 
    logger.Error("This is an Error message"); 
    logger.Fatal("This is a Fatal error message"); 
}

When we run the program, the following information will be written to the "file.txt" in the application directory:

Program.Main This is a Trace message 
Program.Main This is a Debug message 
Program.Main This is an Info message 
Program.Main => Program.A Trace AAA 
Program.Main => Program.A Debug AAA 
Program.Main => Program.A Info AAA 
Program.Main => Program.A => Program.B Trace BBB 
Program.Main => Program.A => Program.B Debug BBB 
Program.Main => Program.A => Program.B Info BBB 
Program.A => Program.B => Program.C Info CCC 
Program.Main => Program.A => Program.B Warn BBB 
Program.Main => Program.A => Program.B Error BBB 
Program.Main => Program.A => Program.B Fatal BBB 
Program.Main => Program.A Warn AAA 
Program.Main => Program.A Error AAA 
Program.Main => Program.A Fatal AAA 
Program.Main This is a Warn message 
Program.Main This is an Error message 
Program.Main This is a Fatal error message

At the same time, we get this fancy colored output on the console:

Now let's modify our configuration a bit. The typical requirement is to have a different level of detail depending on the output. For example, we only want messages whose level is Info and higher written to the console and we want ALL messages to be written to the file. With NLog, you only need to change the <rules /> section. No changes to the C# source code are necessary:

<rules> 
  <logger name="*" minlevel="Info" writeTo="console"/> 
  <logger name="*" minlevel="Trace" writeTo="file"/> 
</rules> 

After running the program we find that Trace and Debug messages are only found in the file and aren't displayed on the console.

Logging configuration

It's now time to describe the NLog configuration mechanism. Unlike other tools, NLog attempts to automatically configure itself on startup, by looking for the configuration files in some standard places. The following locations will be searched when executing a stand-alone *.exe application:

• standard application configuration file (usually applicationname.exe.config)
• applicationname.exe.nlog in application's directory
• NLog.config in application's directory
• NLog.dll.nlog in a directory where NLog.dll is located
• file name pointed by the NLOG_GLOBAL_CONFIG_FILE environment variable (if defined)

In case of an ASP.NET application, the following files are searched:

• standard web application file web.config
• web.nlog located in the same directory as web.config
• NLog.config in application's directory
• NLog.dll.nlog in a directory where NLog.dll is located
• file name pointed by the NLOG_GLOBAL_CONFIG_FILE environment variable (if defined)

The .NET Compact Framework doesn't recognize application configuration files (*.exe.config) nor environmental variables, so NLog only looks in these locations:

• applicationname.exe.nlog in application's directory
• NLog.config in application's directory
• NLog.dll.nlog in a directory where NLog.dll is located

Configuration file format

NLog supports two configuration file formats:

• configuration embedded within the standard *.exe.config or web.config file
• simplified configuration, stored in a separate file

In the first variant, we use a standard configSections mechanism, which makes our file look like this:

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

The simplified format is the pure XML having the <nlog /> element as its root. The use of namespaces is optional, but it enables the Intellisense in Visual Studio.

<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" 
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"> 
</nlog> 

Note that NLog config file is case-insensitive when not using namespaces and is case-sensitive when you use them. Intellisense only works with case-sensitive configurations.

Configuration elements

You can use the following elements as children to <nlog />. The first two elements from the list are required to be present in all NLog configuration files, the remaining ones are optional and can be useful in advanced scenarios.

• <targets /> - defines log targets/outputs
• <rules /> - defines log routing rules
• <extensions /> - loads NLog extensions from the *.dll file
• <include /> - includes external configuration file
• <variable /> - sets the value of a configuration variable

Targets

The <targets /> section defines log targets/outputs. Each target is represented by the <target /> element. There are two attributes required for each target:

• name - target name
• type - target type - such as "File", "Database", "Mail". When using namespaces this attribute is named xsi:type.

In addition to these, targets usually accept other parameters, which influence the way diagnostic traces are written. Each target has a different set of parameters, they are described in detail on project's homepage and they are context-sensitive Intellisense is also available in Visual Studio.

For example - the "File" target accepts the fileName parameter which defines output file name and the Console target has the error parameter which determines whether the diagnostic traces are written to standard error (stderr) instead of standard output (stdout) of the process.

NLog provides many predefined targets. They are described on the project's homepage. It's actually very easy to create your own target - it requires about 15-20 lines of code and is described in the documentation.

Rules

Log routing rules are defined in the <rules /> section. It is a simple routing table, where we define the list of targets that should be written to for each combination of source/logger name and log level. Rules are processed starting with the first rule in the list. When a rule matches, log messages are directed to target(s) in that rule. If a rule is marked as final, rules beneath the current rule are not processed.

Each routing table entry is a <logger /> element, which accepts the following attributes:

• name - source/logger name (may include wildcard characters *)
• minlevel - minimal log level for this rule to match
• maxlevel - maximum log level for this rule to match
• level - single log level for this rule to match
• levels - comma separated list of log levels for this rule to match
• writeTo - comma separated list of target that should be written to when this rule matches.
• final - make this rule final. No further rules are processed when any final rule matches.

Some examples:

• <logger name="Name.Space.Class1" minlevel="Debug" writeTo="f1" /> - all messages from the Class1 in the Name.Space whose level is Debug or higher are written to the "f1" target.
• <logger name="Name.Space.Class1" levels="Debug,Error" writeTo="f1" /> - all messages from the Class1 in the Name.Space whose level is either Debug or Error or higher are written to the "f1" target.
• <logger name="Name.Space.*" writeTo="f3,f4" /> - messages from any class in the Name.Space namespace are written to both "f3" and "f4" targets regardless of their levels.
• <logger name="Name.Space.*" minlevel="Debug" maxlevel="Error" final="true" /> - messages from any class in the Name.Space namespace whose level is between Debug and Error (which makes it Debug,Info,Warn,Error) are rejected (as there's no writeTo clause) and no futher rules are processed for them (because of the final="true" setting)

In the simplest cases the entire logging configuration consists of a single <target /> and a single <logger /> rule that routes messages to this target depending on their level. As the application grows, adding more targets and rules is very simple.

Contextual information

One of NLog's strongest assets is the ability to use layouts. They include pieces of text surrounded by a pair of "${" (dollar sign + left curly brace) and "}" (right curly brace). The markup denotes "layout renderers" which can be used to insert pieces of contextual information into the text. Layouts can be used in many places, for example they can control the format of information written on the screen or sent to a file, but also to control the file names themselves. This is very powerful, which we'll see in a moment.

Let's assume, that we want to augment each message written to the console with:

• current date and time
• name of the class and method that emitted the log message
• log level
• message text

This is very easy:

<target name="c" xsi:type="Console" 
        layout="${longdate} ${callsite} ${level} ${message}"/> 

We can make each messages for each logger go to a separate file, as in the following example:

<target name="f" xsi:type="File" fileName="${logger}.txt"/> 

Ay you can see the ${logger} layout renderer was used in the fileName attribute, which causes each log message to be written to the file whose name includes the logger name. The above example will create the following files:

• Name.Space.Class1.txt
• Name.Space.Class2.txt
• Name.Space.Class3.txt
• Other.Name.Space.Class1.txt
• Other.Name.Space.Class2.txt
• Other.Name.Space.Class3.txt
• ...

It's a frequent requirement to be able to keep log files for each day separate. This is trivial, too, thanks to the ${shortdate} layout renderer:

<target name="f" xsi:type="File" filename="${shortdate}.txt"/> 

How about givin each employee their own log file? The ${windows-identity} layout renderer will do the trick:

<target name="f" xsi:type="File" filename="${windows-identity:domain=false}.txt"/> 

Thanks to this simple setting NLog will create a set of files named after our employees' logins:

1. Administrator.txt
2. MaryManager.txt
3. EdwardEmployee.txt
4. ...

More complex cases are of course possible. The following sample demonstrates the way of creating a distinct log file for each person per day. Log files for each day are stored in a separate directory:

<target name="f" xsi:type="File" 
        filename="${shortdate}/${windows-identity:domain=false}.txt"/> 

This creates the following files:

1. 2006-01-01/Administrator.txt
2. 2006-01-01/MaryManager.txt
3. 2006-01-01/EdwardEmployee.txt
4. 2006-01-02/Administrator.txt
5. 2006-01-02/MaryManager.txt
6. 2006-01-02/EdwardEmployee.txt
7. ...

NLog provides many predefined layout renderers. They are described on the http://www.nlog-project.org/layoutrenderers.html page. It's very easy to create your own layout renderer. It just takes 15-20 lines of code and is described in the documentation section of the project website.

Include files

It's sometimes desired to split the configuration file into many smaller ones. NLog provides an include file mechanism for that. To include an external file, you simply use It's worth noting that the fileName attribute, just like most attributes in NLog config file(s), may include dynamic values using the familiar ${var} notation, so it's possible to include different files based on environmental properties. The following configuration example demonstrates this, by loading file whose name is derived from the name of the machine we're running on.

<nlog> 
  ... 
  <include file="${basedir}/${machinename}.config"/> 
  ... 
</nlog> 

Variables let us write complex or repeatable expression (such as file names) in a concise manner. To define a variable we use the <variable name="var" value="xxx" /> syntax. Once defined, variables can be used as if they were layout renderers - by using ${var} syntax, as demonstrated in the following example:

<nlog> 
  <variable name="logDirectory" value="${basedir}/logs/${shortdate}"/> 
  <targets> 
    <target name="file1" xsi:type="File" filename="${logDirectory}/file1.txt"/> 
    <target name="file2" xsi:type="File" filename="${logDirectory}/file2.txt"/> 
  </targets> 
</nlog> 

Automatic reconfiguration

The configuration file is read automatically at program startup. In a long running process (such as a Windows service or an ASP.NET application) it's sometimes desirable to temporarily increase the log level without stopping the application. NLog can monitor logging configuration files and re-read them each time they are modified. To enable this mechanism, you simply set <nlog autoReload="true" /> in your configuration file. Note that automatic reconfiguration supports include files, so each time one of the files include is changed, the entire configuration gets reloaded.

Troubleshooting logging

Sometimes our application doesn't write anything to the log files, even though we have supposedly configured logging properly. There can be many reasons for logs not being written. The most common problem are permissions, usually in an ASP.NET process, where the aspnet_wp.exe or w3wp.exe process may not have write access to the directory where we want to store logs. NLog is designed to swallow run-time exceptions that may result from logging. The following settings can change this behavior and/or redirect these messages.

• <nlog throwExceptions="true" />- adding throwExceptions attribute in the config file causes NLog not to mask exceptions and pass them to the calling application instead. This attribute is useful at deployment time to quickly locate any problems. It's recommended to turn throwExceptions to "false" as soon as the application is properly configured to run, so that any accidental logging problems won't crash the application.
• <nlog internalLogFile="file.txt" />- adding internalLogFile cause NLog to write its internal debugging messages to the specified file. This includes any exceptions that may be thrown during logging.
• <nlog internalLogLevel="Trace|Debug|Info|Warn|Error|Fatal" /> - determines internal log level. The higher the level, the less verbose the internal log output.
• <nlog internalLogToConsole="false|true" /> - sends internal logging messages to the console.
• <nlog internalLogToConsoleError="false|true" /> - sends internal logging messages to the console error output (stderr).

Asynchronous processing, wrapper and compound targets

NLog provides wrapper and compound targets which modify other targets' behaviour by adding features like:

• asynchronous processing (wrapped target runs in a separate thread)
• retry-on-error
• load balancing (round-robin targets)
• buffering
• filtering
• backup targets (failover)
• and others described on http://www.nlog-project.org/targets.html

To define a wrapper or compound target in the configuration file, simply nest a target node within another target node. You can even wrap a wrapper target. There are no limits on depth. For example, to add asynchronous logging with retry-on-error functionality add this to your configuration file:

<targets> 
  <target name="n" xsi:type="AsyncWrapper"> 
    <target xsi:type="RetryingWrapper"> 
      <target xsi:type="File" fileName="${file}.txt"/> 
    </target> 
  </target> 
</targets> 

Because asynchronous processing is a common scenario, NLog supports a shorthand notation to enable it for all targets without the need to specify explicit wrappers. You simply set <targets async="true" /> and all your targets will be wrapped with the AsyncWrapper target.

Programmatic configuration

In certain cases you may choose not to use configuration file, but to configure NLog using the provided API. Full description of this feature is beyond the scope of this article, so let's just outline the steps necessary to make it work. To configure NLog in code you need to:

1. Create a LoggingConfiguration object that will hold the configuration
2. Create one or more targets (objects of classes inheriting from Target)
3. Set the properties of the targets
4. Define logging rules through LoggingRule objects and add them to configuration's LoggingRules
5. Activate the configuration by assigning the configuration object to LogManager.Configuration

This sample demonstrates the programmatic creation of two targets: one is a colored console and the other is a file and rules that send messages to them for messages whose level is Debug or higher.

using NLog; 
using NLog.Targets; 
using NLog.Config; 
using NLog.Win32.Targets; 
 
class Example 
{ 
    static void Main(string[] args) 
    { 
        // Step 1. Create configuration object 
         
        LoggingConfiguration config = new LoggingConfiguration(); 
         
        // Step 2. Create targets and add them to the configuration 
 
        ColoredConsoleTarget consoleTarget = new ColoredConsoleTarget(); 
        config.AddTarget("console", consoleTarget); 
         
        FileTarget fileTarget = new FileTarget(); 
        config.AddTarget("file", fileTarget); 
         
        // Step 3. Set target properties 
         
        consoleTarget.Layout = "${date:format=HH\\:MM\\:ss} ${logger} ${message}"; 
        fileTarget.FileName = "${basedir}/file.txt"; 
        fileTarget.Layout = "${message}"; 
         
        // Step 4. Define rules 
         
        LoggingRule rule1 = new LoggingRule("*", LogLevel.Debug, consoleTarget); 
        config.LoggingRules.Add(rule1); 
 
        LoggingRule rule2 = new LoggingRule("*", LogLevel.Debug, fileTarget); 
        config.LoggingRules.Add(rule2); 
         
        // Step 5. Activate the configuration 
 
        LogManager.Configuration = config; 
         
        // Example usage 
 
        Logger logger = LogManager.GetLogger("Example"); 
        logger.Trace("trace log message"); 
        logger.Debug("debug log message"); 
        logger.Info("info log message"); 
        logger.Warn("warn log message"); 
        logger.Error("error log message"); 
        logger.Fatal("fatal log message"); 
    } 
}

What else is possible with NLog?

NLog supports some more logging scenarios, which couldn't be fully described here. See the links below for more information:

• exception logging - http://sourceforge.net/mailarchive/forum.php?thread_id=6766833&forum_id=41984
• conditional expressions language - http://www.nlog-project.org/conditions.html
• NLogViewer - real-time log viewer application (currently in pre-alpha stage) - http://viewer.nlog-project.org/

Last updated: 2006-07-10 11:32:55