LowLevelDesign.NLog.Ext and ETW targets for NLog


I really like the NLog library and I use it pretty often in my projects. Some time ago I wrote a post in which I showed you my preferred debug and production configuration. Other day I presented you a simple layout renderer for assembly versions. Today, I would like to inform you that all those goodies 😉 are available in my brand new LowLevelDesign.NLog.Ext Nuget package.

Additionally, you may find in it two ETW NLog targets. ETW (Event Tracing for Windows) is a very effective way of logging and its support in kernel makes it a great choice for verbose/trace/debug logs. Moreover, if you are using Windows Performance Toolkit in your performance analysis, providing your own ETW messages will help you correlate system events with methods in your application. ETW infrastructure is highly customizable (check Semantic Logging Application Block to see how your logs might look like and how they might be consumed:)).

Our first ETW NLog target is really simple, based on EventProvider from System.Diagnostics.Eventing:

using NLog;
using NLog.Targets;
using System;
using System.Diagnostics.Eventing;

namespace LowLevelDesign.NLog.Ext
{
    [Target("EventTracing")]
    public sealed class NLogEtwTarget : TargetWithLayout
    {
        private EventProvider provider;
        private Guid providerId = Guid.NewGuid();

        /// <summary>
        /// A provider guid that will be used in ETW tracing.
        /// </summary>
        public String ProviderId {
            get { return providerId.ToString(); }
            set {
                providerId = Guid.Parse(value);
            }
        }

        protected override void InitializeTarget() {
            base.InitializeTarget();

            // we will create an EventProvider for ETW
            try {
                provider = new EventProvider(providerId);
            } catch (PlatformNotSupportedException) {
                // sorry 😦
            }
        }

        protected override void Write(LogEventInfo logEvent) {
            if (provider == null || !provider.IsEnabled()) {
                return;
            }
            byte t;
            if (logEvent.Level == LogLevel.Debug || logEvent.Level == LogLevel.Trace) {
                t = 5;
            } else if (logEvent.Level == LogLevel.Info) {
                t = 4;
            } else if (logEvent.Level == LogLevel.Warn) {
                t = 3;
            } else if (logEvent.Level == LogLevel.Error) {
                t = 2;
            } else if (logEvent.Level == LogLevel.Fatal) {
                t = 1;
            } else {
                t = 5; // let it be verbose
            }

            provider.WriteMessageEvent(this.Layout.Render(logEvent), t, 0);
        }

        protected override void CloseTarget() {
            base.CloseTarget();

            provider.Dispose();
        }
    }
}

The second one is built on top of the Microsoft.Diagnostics.Tracing Nuget package (by Vance Morrison). Starting from .NET4.5 the EventSource class is available in the framework, but if you want your code to work also with .NET4.0 (as me) you need to use the Nuget package. The code of the extended ETW target is as follows:

using Microsoft.Diagnostics.Tracing;
using NLog;
using NLog.Targets;
using System;

namespace LowLevelDesign.NLog.Ext
{
    [Target("ExtendedEventTracing")]
    public sealed class NLogEtwExtendedTarget : TargetWithLayout
    {
        [EventSource(Name = "LowLevelDesign-NLogEtwSource")]
        public sealed class EtwLogger : EventSource
        {
            [Event(1, Level = EventLevel.Verbose)]
            public void Verbose(String LoggerName, String Message) {
                WriteEvent(1, LoggerName, Message);
            }

            [Event(2, Level = EventLevel.Informational)]
            public void Info(String LoggerName, String Message) {
                WriteEvent(2, LoggerName, Message);
            }

            [Event(3, Level = EventLevel.Warning)]
            public void Warn(String LoggerName, String Message) {
                WriteEvent(3, LoggerName, Message);
            }

            [Event(4, Level = EventLevel.Error)]
            public void Error(String LoggerName, String Message) {
                WriteEvent(4, LoggerName, Message);
            }

            [Event(5, Level = EventLevel.Critical)]
            public void Critical(String LoggerName, String Message) {
                WriteEvent(5, LoggerName, Message);
            }

            public readonly static EtwLogger Log = new EtwLogger();
        }

        protected override void Write(LogEventInfo logEvent)
        {
            if (!EtwLogger.Log.IsEnabled())
            {
                return;
            }
            if (logEvent.Level == LogLevel.Debug || logEvent.Level == LogLevel.Trace) {
                EtwLogger.Log.Verbose(logEvent.LoggerName, Layout.Render(logEvent));
            } else if (logEvent.Level == LogLevel.Info) {
                EtwLogger.Log.Info(logEvent.LoggerName, Layout.Render(logEvent));
            } else if (logEvent.Level == LogLevel.Warn) {
                EtwLogger.Log.Warn(logEvent.LoggerName, Layout.Render(logEvent));
            } else if (logEvent.Level == LogLevel.Error) {
                EtwLogger.Log.Error(logEvent.LoggerName, Layout.Render(logEvent));
            } else if (logEvent.Level == LogLevel.Fatal) {
                EtwLogger.Log.Critical(logEvent.LoggerName, Layout.Render(logEvent));
            }
        }
    }
}

The biggest difference between them is that the second one integrates much better with ETW infrastructure. Thanks to the dynamic manifest generation, events from the second target have more meaningful names and characteristics in tools such as PerfView or WPA:

capture-perfview2

capture-wpa2

compared to events generated by the first target:

capture-perfview1

capture-wpa1

After examining the above output there should be no doubt which target should you use. I recommend NLogEtwExtendedTarget except cases when you need control over GUID of your ETW provider. It’s impossible to change the GUID for LowLevelDesign-NLogEtwSource (EventSources use a well-defined, public mechanism (RFC 4122) for converting a name to a GUID) so logs from applications that use this target will always have the same provider. I don’t consider this a big problem as they are still distinguishable by process id or name.

There is one more thing that should attract your attention in the above screenshots. Have you noticed activity ids for our events? Yes, they are there and it is really easy to enable them. We used to call Trace.CorrelationManager.ActivityId = newActivityId; at the beginning of the activity scope, now we need to make one additional call: EventSource.SetCurrentThreadActivityId(newActivityId, out prevActivityId);. My test application looks as follows:

using System;
using System.Diagnostics;
using NLog;
using LowLevelDesign.NLog.Ext;
using Microsoft.Diagnostics.Tracing;

public static class TestNLog
{
    private static readonly Logger logger = LogManager.GetLogger("TestLogger");

    public static void Main(String[] args) {
        Guid prevActivityId;
        Guid newActivityId = Guid.NewGuid();
        Trace.CorrelationManager.ActivityId = newActivityId;
        EventSource.SetCurrentThreadActivityId(newActivityId, out prevActivityId);

        Console.WriteLine("Trace source logging");

        logger.Info("Start");

        Console.WriteLine("In the middle of tracing");

        logger.ErrorException("Error occured", new Exception("TestException"));

        logger.Info("End");

        EventSource.SetCurrentThreadActivityId(prevActivityId);
        Trace.CorrelationManager.ActivityId = prevActivityId;
    }
}

UPDATE: @Scooletz with his comment inspired me to add a shortcut for scoping traces. The newly added class is named EtwContextScope and is available in version 1.2.1 of the package. The above Main method using it will look as follows:

    public static void Main(String[] args)
    {
        using (new EtwContextScope())
        {
            Console.WriteLine("Trace source logging");

            logger.Info("Start");

            Console.WriteLine("In the middle of tracing");

            logger.ErrorException("Error occured", new Exception("TestException"));

            logger.Info("End");
        }
    }

And its configuration file:

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

  <startup>
    <supportedRuntime version="v4.0" sku=".NETFramework,Version=v4.0" />
  </startup>

  <nlog internalLogToConsole="true" internalLogLevel="Debug" throwExceptions="true">
    <extensions>
      <add prefix="lld" assembly="LowLevelDesign.NLog.Ext" />
    </extensions>
    <targets>
      <target name="console" type="ColoredConsole" layout="${longdate}|${uppercase:${level}}|${message}${onexception:|Exception occurred\:${exception:format=tostring}}" />
      <target name="etw" type="lld.EventTracing" providerId="ff1d574a-58a1-45f1-ae5e-040cf8d3fae2" layout="${longdate}|${uppercase:${level}}|${message}${onexception:|Exception occurred\:${exception:format=tostring}}" />
      <target name="eetw" type="lld.ExtendedEventTracing" layout="${longdate}|${uppercase:${level}}|${message}${onexception:|Exception occurred\:${exception:format=tostring}}" />
    </targets>
    <rules>
      <logger name="TestLogger" minlevel="Debug" writeTo="console" />
      <logger name="TestLogger" minlevel="Debug" writeTo="etw" />
      <logger name="TestLogger" minlevel="Debug" writeTo="eetw" />
    </rules>
  </nlog>
</configuration>

As ETW events are transferred via kernel buffers you need to use special tools or libraries to collect them. You may either create your own solution with a help of the already mentioned Semantic Logging Block or try to use tools such as PerfView or WPR. The screenshot below shows you a PerfView capture window with enabled providers from my test application (notice that we can reference the extended ETW target only by its name):

Capture

If you are looking for information how to use other tools or you want to know more about ETW tracing I recommend a great Vance Morisson’s blog. If you happen to know Polish have a look also at Michał’s post.

All source code from this post is available for download on my codeplex page and my Nuget package waits for you here 🙂

LowLevelDesign.NLog.Ext and ETW targets for NLog

8 thoughts on “LowLevelDesign.NLog.Ext and ETW targets for NLog

  1. The last example with an activityId would look better if you provided some kind of activityIdScope, just to make it… scopable. Sth like OperationContextScope.

    Got to dive dipper into ETW topic.

  2. Ilan says:

    I’m trying to find a way to log events into the Diagnostics hub in VS2015. Do you know whether ETW events are supposed to show up there? I’ve tried out Nlog.Etw (thanks) and AFAIK have everything setup correctly (other targets like console and file are working) but it doesn’t seem to appear in the Diagnostics Tools. I haven’t checked something like PerfView yet to confirm that the ETW events are indeed being logged.

    1. Hi Ilan, sorry for such a delay with my response but I was on vacations. I’m not sure about the Diagnostics Hub but I am guessing it’s not automatically detecting ETW events from your app. You definitely should try with perfview to make sure events are there. If I find something interesting about the Diagnostics Hub I will let you know.

  3. pregunton says:

    Hi mister,

    i’m Carlos, ASP.NET developer, now NET 4.6.1, I’m fully newbie with debugging, logging high level like you, guru level IMHO.

    I have seen your pages- blog
    http://www.lowleveldesign.org/
    https://lowleveldesign.wordpress.com
    http://www.codeproject.com/Articles/639494/Life-of-Exception-in-ASP-NET

    My comments about it:

    Now, in your ASP.NET applications in production environment, which tools you use?

    Via twitter, ASP.NET Health Monitoring not used today.

    Do you use Diagnostics Kit and Diagnostics Tools in production environment? any getting started guide – step by step for install it Diagnostics Kit and Diagnostics Tools ?

    IMHO, you recommend NLog or Serilog for logging, and maybe use Elasticsearch Logstash hKibana (ELK) or anothers like Splunk or Exceptionless.
    Diagnostics Kit can be collect logs too.

    Anyones too uses Glimpse.

    Finally, which are your good patterns and practices for your ASP.NET applications and for troubleshooting hem?

    Thanks a lot. Thanks in advanced. Sorry for inconveniences.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s