NLog: rules and filters

In Confirmit we use NLog library for logging in .NET applications. Although there is a documentation for this library, I found it hard to understand how the loggers work. In this article, I’ll try to explain, how rules and filters are used by NLog. Let’s start.

How to configure NLog

We’ll start with a small reminder, what we can do with NLog configuration. Simple configuration usually is an XML file (e.g. NLog.config):

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

  <targets>
    <target name="target1" xsi:type="ColoredConsole" layout="Access Log|${level:uppercase=true}|${logger}|${message}">
      <highlight-row condition="true" foregroundColor="red"/>
    </target>
    <target name="target2" xsi:type="ColoredConsole" layout="Common Log|${level:uppercase=true}|${logger}|${message}">
      <highlight-row condition="true" foregroundColor="green"/>
    </target>
    <target name="target3" xsi:type="ColoredConsole" layout="Yellow Log|${level:uppercase=true}|${logger}|${message}">
      <highlight-row condition="true" foregroundColor="yellow"/>
    </target>
  </targets>

  <rules>
    <logger name="*" minlevel="Warn" writeTo="target1,target2,target3" />
  </rules>
</nlog>

You can load this configuration with a single line of code:

LogManager.Configuration = new XmlLoggingConfiguration("NLog.config");

What can we do with NLog configuration? We can set several targets per rule:

<rules>
  <logger name="*" minlevel="Warn" writeTo="target1,target2,target3" />
</rules>

We can define which log levels we want to log:

<rules>
  <logger name="*" minlevel="Warn" writeTo="target1" />
  <logger name="*" levels="Debug,Warn,Info" writeTo="target2" />
</rules>

We can set filters for each rule:

<rules>
  <logger name="*" minlevel="Info" writeTo="target1">
    <filters defaultAction='Log'>
      <when condition="contains('${message}','Common')" action="Ignore" />
    </filters>
  </logger>
</rules>

And finally, we can use nested rules:

<rules>
  <logger name="*" minlevel="Info" writeTo="target1">
    <logger name="*" minlevel="Warn" writeTo="target2" />
  </logger>
</rules>

It is time to take a look at how it all works.

Construction of a logger configuration

When you request an instance of a logger,

var commonLogger = LogManager.GetLogger("Common");

NLog either takes it from its cache or creates a new one (see here). In the last case, it will create a new configuration for loggers with the given name. Let's take a closer look at this configuration.

In general, the configuration of a logger contains a separate chain of log targets with corresponding filters for each log level (Trace, Debug, Info, Warn, Error, Fatal) (see here). Now we'll see, how these chains are constructed.

The main method, responsible for constructions of these chains is GetTargetsByLevelForLogger of LogFactory class. Here is how it works. It traverses all rules in the NLog configuration. First of all, it checks if the name of the rule corresponds to the name of the logger. Names of rules support wildcard symbols as we use for file system objects:

• * - any sequence of symbols
• ? - any single symbol

So rule name '*' corresponds to any name of a logger, and 'Common*' corresponds to all loggers with names starting with 'Common'.

If the name of the rule does not correspond to the name of the logger, this rule is not used with all its subrules. Otherwise, the method gets all log levels, for which this rule is enabled. For each such level NLog adds all targets of the rule to the corresponding chain of targets with filters of the rule.

There is one more important step in the construction of the target chains. If current rule is marked as final and its name corresponds to the name of the logger, then NLog stops here constructions of all chains of targets for all log levels enabled for the rule. It means, that neither following rules, nor nested rules will add anything to these chains of targets. They are completely constructed and will not be changed. It means, that there is no point in writing something like this:

<rules>
  <logger name="*" minlevel="Info" writeTo="target1" final="true">
    <logger name="*" minlevel="Warn" writeTo="target2" />
  </logger>
</rules>

Nothing will ever come to target2. But it has a point to write this configuration:

<rules>
  <logger name="*" minlevel="Warn" writeTo="target1" final="true">
    <logger name="*" minlevel="Info" writeTo="target2" />
  </logger>
</rules>

As the outer rule is not enabled for the Info log level, targets chain for this level will not be frozen on the outer rule. So all Info messages will go to the target2.

After the targets of the rule are added to corresponding chains of targets, all subrules of the current rule are recursively processed using the same algorithm. It happens regardless of log levels enabled for the parent rule.

Finally, the configuration for the logger is constructed. It contains chains of targets with filters for each possible log level:

Now it is time to use the configuration.

Usage of a logger configuration

We'll start with a simple thing. Logger class has IsEnabled method and corresponding IsXXXEnabled properties (IsDebugEnabled, IsInfoEnabled, ...). How do they work? Actually, it just checks if the chain of targets for the corresponding log level is not empty (see here). It means that filters never influence values of these properties and method.

Next, let me explain what happens when you want to log some message. As you can guess, the logger takes the chain of targets for the corresponding log level. It starts to process links of the chain one by one. For each link, the logger decides if the message should be written in the corresponding target and if the processing of the chain should be stopped here. It is done using filters. Let me show you how NLog filters work.

Here is how filters are defined in the configuration:

<rules>
  <logger name="*" minlevel="Info" writeTo="target1">
    <filters defaultAction='Log'>
      <when condition="contains('${message}','Common')" action="Ignore" />
    </filters>
  </logger>
</rules>

A usual filter has a boolean condition. Here you can think, that filter returns true or false for each message. But it is not true. Filters actually return value of FilterResult type. If the condition of a filter evaluates to true, then the filter returns value defined by action attribute (it is Ignore in our example). If the condition evaluates to false, the filter returns Neutral. It means that this filter does not want to decide what to do with the message.

You can see how the chain of targets is processed here. For each target result of filters is calculated using GetFilterResult method. This result is equal to the result of the first filter that is not Neutral. It means, that if some filter returns value different from Neutral, all filters after this will not be executed.

But what happens if all filters returned Neutral value? In this case, the default value is used. This value is set by defaultAction attribute of filters element of a rule. How do you think, what is the default value for the defaultAction? You are right if you think it is Neutral. It means, that the whole chain of filters can return Neutral as a result. In this case, NLog considers it as Log. That is the message will still be written into the target (see here).

As you can guess if the filter result is Ignore or IgnoreFinal the message will not be written into the target. If the result is Log or LogFinal the message will be written into the target. But what is the difference between Ignore and IgnoreFinal and between Log or LogFinal? It is simple. In the case of IgnoreFinal and LogFinal NLog stops the processing of the chain of targets here and writes nothing in the targets after the current.

Conclusion

Analysis of NLog code helped me a lot in understanding how its rules and filters work. I hope it will help you as well. Good luck!