Logging Configuration File

The logging can be customized by providing a configuration file to NLog, e.g. by creating an "nlog.config" file in the same folder as where the executable resides.

This article describes the actionETL specific aspects of logging, and some of the more common logging settings; please also see the NLog configuration, troubleshooting, and overall wiki, which documents its extensive capabilities.

This nlog.config file would replicate the default logging settings, and is described below, together with some optional settings.

<nlog>

This tag controls NLog internal logging, which is useful for troubleshooting NLog itself if logging is not working as expected, e.g. due to configuration errors. In particular:

  • throwExceptions controls whether NLog should throw exceptions when there is a logging issue. It is good practice to set this to true in Dev and Test environments; consider what the appropriate setting is for production - is it more important to know how the application ran (true), or is it more important to complete execution even if the logs won't be complete (false).
  • internalLogLevel defaults to warnings and above - increase NLog internal logging to Info or Debug when troubleshooting NLog issues
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
    xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"

    autoReload="false"
    throwExceptions="true"
    internalLogFile="nlog-internal.log"
    internalLogLevel="Warn"
    internalLogToConsole="true"
>

<extensions>

actionETL adds two extensions to NLog.

<extensions>
    <add assembly="actionETL" />
</extensions>

${currenttaskid}

Specifying ${currenttaskid} in a layout outputs the Task.CurrentId value (if available) of the logging call. This can be used together with the ${threadid} layout to trace how threads and tasks are used, e.g. when developing a new worker that internally runs multiple threads, but is otherwise rarely needed.

Important

Avoid using the default BufferingWrapper asynchronous logging target together with the ${threadid} layout, since that logs the wrong thread id. Instead use a synchronous logging target, e.g. the File target, while troubleshooting with the ${threadid} layout.

ThrottleTargetWrapper

An optional wrapper target that aggregates similar consecutive log messages, which can be useful when enabling Debug or Trace logging with high volume data. The aggregation only applies to messages that have the same: Log level, Locator, Category, ThreadId (if present), and Message.

Syntax:

<target name="ToFile" xsi:type="ThrottleTargetWrapper" TimeoutSeconds="5" MaxThrottled="10000">
    ... insert actual target here ...
</target>

Where:

  • TimeoutSeconds - Maximum time before outputting currently aggregated messages
  • MaxThrottled - Maximum number of aggregated messages before outputting them

<variable> and Layouts

Declaring variables simplifies using the same layout with multiple targets.

Layouts define what to output to the logging targets, and the formatting of this output.

In particular:

  • ${logger} - The logger name, which is normally populated by a Locator string, e.g. Locator. This makes it easy to adjust logging for whole sub trees of the worker hierarchy, see <rules> below.
  • ${event-properties:item=Category} - Category is a string that classifies log messages, see Logging Messages
  <variable name="header-layout" 
    value="DateTime | Level | Locator | Category | Message"/>

  <variable name="file-body-layout-stacktrace" 
    value="${longdate} | ${level:uppercase=true} | ${logger} | ${event-properties:item=Category} | ${message}${onexception:${literal:text= }EXCEPTION OCCURRED\: ${exception:format=tostring,data,method:maxInnerExceptionLevel=10:innerFormat=tostring,data,method:maxInnerExceptionLevel=10}}"/>

  <variable name="console-body-layout" 
    value="${longdate} | ${level:uppercase=true} | ${logger} | ${event-properties:item=Category} | ${message}${onexception:${literal:text= }EXCEPTION OCCURRED\: ${exception:format=type,message,data,method:maxInnerExceptionLevel=10:innerFormat=shorttype,message,data,method:maxInnerExceptionLevel=10}}"/>

<targets>

Targets define the available logging destinations, and are controlled via attributes:

  • name - The target name, used by <rules>
  • xsi:type - specifies which one of the many available targets is used
  • layout - Controls what to output, and its formatting

Most targets will also have their own target specific attributes to control how they work.

This example logs to a "File" target, wrapped in a "BufferingWrapper" target for improved performance. It also logs to the "ColoredConsole" target.

<targets>

    <target name="ToFile" xsi:type="BufferingWrapper" bufferSize="100" flushTimeout="1000" 
            slidingTimeout="false">
        <target xsi:type="File" fileName="${processname}.log" deleteOldFileOnStartup="true" 
                header="${var:header-layout}" 
                layout="${var:file-body-layout-stacktrace}"/>
    </target>

    <target name="ToConsole" xsi:type="ColoredConsole" header="${var:header-layout}" 
            layout="${var:console-body-layout}"/>

</targets>

<rules>

The rules section controls which log messages get sent to one or more targets, or get discarded.

Each <logger> routes log messages from log sources to targets:

  • name - Specifies which logger names (i.e. the worker and worker system Locator as well as input and output and error output Locator strings) should be included. It supports * wild-cards, but only at the start and end, not in the middle of the Locator name. Some examples:
    • "*" - All loggers
    • "*Sales*" - Only affect workers and ports with "Sales" somewhere in their Locator
    • "*.Inputs[*" - Only affect all input ports. You can replace "Inputs" with "Outputs" or "ErrorOutputs" to instead affect those ports.
    • "/Root/Extracts/Sales*" - Only affect workers and ports beginning with "/Root/Extracts/Sales", including any descendant workers
    • "/Root/Extracts/Sales/*" - Only affect workers and ports that are descendants of the "/Root/Extracts/Sales" worker
    • "/Root/Extracts/Sales" - Only affect the "/Root/Extracts/Sales" worker, but not its ports
    • "/Root/Extracts/Sales.*" - Only affect the ports of the "/Root/Extracts/Sales" worker
    • "/Root/Extracts/Sales.Inputs*" - Only affect the input ports of the "/Root/Extracts/Sales" worker. You can replace "Inputs" with "Outputs" or "ErrorOutputs" to instead affect those ports.
    • "/Root/Extracts/Sales.Inputs[LeftInput]" - Only affect the "LeftInput" input port of the "/Root/Extracts/Sales" worker. You can replace "Inputs" with "Outputs" or "ErrorOutputs" to instead affect those ports.
    • "/UniqueName*" - Only affect worker system named "UniqueName", useful when multiple worker systems use the same configuration
  • 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 targets that should be written to when this rule matches
  • final - Make this rule final. Rules are processed sequentially in the order they appear in the configuration file. No further rules are processed when any final rule matches.
  • enabled - Setting enabled to false disables this rule. Disabled rules are ignored.

<filters> allow including or excluding log messages based on expressions, and are more flexible (but have a higher overhead) than the above name and wild-card filtering. You can also combine name and - <filters> in the same rule. See filtering for more details.

Examples rules:

<rules>
  <!-- Log "Info" and higher events from all loggers to the "ToFile" target -->
  <logger name="*" minlevel="Info" writeTo="ToFile" />

  <!-- Log "Info" and higher events from all loggers to the "ToConsole" target, 
     except "Info" events where the "Category" does not start with 'System.' -->
  <logger name="*" minlevel="Info" writeTo="ToConsole">
    <filters>
      <when condition="level == LogLevel.Info and not starts-with('${event-properties:item=Category}','System.')" 
            action="Ignore" />
    </filters>
  </logger>

  <!-- Log "Debug" and "Trace" events from all descendants of "/Root/Extracts/Sales" to
       the "ToFile" target. Marked as "final" to avoid double logging with later rules. -->
  <logger name="/Root/Extracts/Sales/*" levels="Debug,Trace" writeTo="ToFile" final="true" />

  <!-- Log "Debug" events from all input ports to the "ToFile" target.
       Marked as "final" to avoid double logging with later rules. -->
  <logger name="*.Inputs[*" level="Debug" writeTo="ToFile" final="true" />

  <!-- Log "Debug" events from "/Root/Extracts/Budget*" and descendants to the
       "ToFile" target, except if the logger (i.e. Locator) contains 'Metadata'. -->
  <logger name="/Root/Extracts/Budget*" level="Debug" writeTo="ToFile">
    <filters>
      <when condition="contains('${logger}','Metadata')" action="Ignore" />
    </filters>
  </logger>
</rules>

<time>

By default, log message timestamps have an accuracy of about 16 milliseconds. This means consecutive log messages might have the same timestamp even though they occurred up to 16 milliseconds apart. This is in most cases perfectly adequate; the accuracy can however be increased to 1 millisecond, which can be useful when comparing order of events logged by different workers.

The default timestamps use local time, this can be changed to UTC.

Please see NLog Time Source for how to configure the <time> tag, and the trade-offs involved.

Note

Irrespective of the <time> configuration, the UTC time is always logged at the start, with category "System.Environment".

See Also