Adding Trace to a .NET application and listening to it

Just yesterday I was chatting with a friend and he was telling me how they are writing a thread-safe logging library for their .NET app. I was astonished to find out that they were completely unaware of the awesome trace library in .NET.

So this post is about how to add configurable tracing to an .NET app and how to use some cool tools to see the log. In case you know about the how-to-add part skip down to the listening part as it talks about some neat tool you may not know about.

Adding trace

The System.Diagnostic namespace contains the tracing API's that are thread-safe, have configurable levels of tracing, zero-foot print with conditional compilation, trace listener support, etc...

First lets define a simple wrapper class over the trace API

 public static class Logger
{
    private static string procName = 
            Process.GetCurrentProcess().ProcessName; 
 
    private static TraceSwitch traceSwitch = 
            new TraceSwitch("AppTraceLevel", null);
 


    [ConditionalAttribute("TRACE")]
    public static void Info(string format, params object[] args)
    {
        Info(string.Format(CultureInfo.InvariantCulture, format, args));
    }

    [ConditionalAttribute("TRACE")]
    public static void Info(string message)
    {
        if(traceSwitch.TraceInfo)
            TraceLine(TraceLevel.Info, message);
    }

    [ConditionalAttribute("TRACE")]
    public static void Error(string format, params object[] args)
    {
        Error(string.Format(CultureInfo.InvariantCulture, format, args));
    }

    [ConditionalAttribute("TRACE")]
    public static void Error(string message)
    {
        if (traceSwitch.TraceError)
            TraceLine(TraceLevel.Error, message);
    }

    
    // TODO: Add Warning/Verbose and other methods in line with Info/Error 
 
    private static void TraceLine(TraceLevel level, string message)
    {
        string traceLevel = null;

        switch (level)
        {
            case TraceLevel.Error:
                traceLevel = "ERROR:  "; break;

            case TraceLevel.Warning:
                traceLevel = "WARNING:"; break;

            case TraceLevel.Info:
                traceLevel = "INFO:   "; break;

            case TraceLevel.Verbose:
                traceLevel = "VERBOSE:"; break;

            default:
                traceLevel = "DEFAULT:"; break;
        }

        string finalMessage = string.Format(
            CultureInfo.InvariantCulture,
            "{0}, {1}, {2}, {3}, {4}", traceLevel, procName, 
            Thread.CurrentThread.ManagedThreadId, DateTime.Now, message);
        
        Trace.WriteLine(finalMessage);
    }
} 

The statement private static TraceSwitch traceSwitch = new TraceSwitch("AppTraceLevel", null); on the top is used to read the trace level from the Config file (more about how to use it below). After that the Log and the Error Methods simply forward the call to TraceLine. TraceLine creates a formatted message and uses Trace.WriteLine (message) to dump it to the Trace.

The app just calls Logger.Info("message") or Logger.Error("message") to trace something.

Note that the methods have conditional compilation attribute on it and hence have zero overhead in case the TRACE symbol is not defined.

Configuring Trace and listening to it

The trace-level and how the actual trace is dumped is configured using an App.Config file that is added to the application to be traced. The file after adding the configuration looks as

 <configuration>
  <system.diagnostics>
    <switches>
      <!--  0-off, 1-error, 2-warn, 3-info, 4-verbose. -->
      <add name="AppTraceLevel" value="4" />
    </switches>

    <trace autoflush="true" indentsize="4">
      <listeners>
        <add name="myListener"
            type="System.Diagnostics.TextWriterTraceListener"
            initializeData="C:\logs\TraceSample.csv" />
        <add name="EventLog"
           type="System.Diagnostics.EventLogTraceListener, 
                 System, Version=2.0.0.0, 
                 Culture=neutral, PublicKeyToken=b77a5c561934e089"
           initializeData="sample application"/>
      </listeners>
    </trace>
  </system.diagnostics>
</configuration>

Here we are setting AppTraceLevel to 4 which means that all tracing is allowed. If you set it to <=2 then calls from our Logger::Info will not be logged.

We also have two different trace listeners configured. One is named myListener which uses the system provided file based tracing and dumps everything to a csv file (c:\logs\TraceSample.csv). We used a csv file because intentionally we chose a format of tracing (see string.Format in Logger::TraceLine) where the trace is comma separated and hence can be easily opened in Microsoft Excel. You can as well name it .txt and use notepad.

The problem with file based tracing is that its not real-time and you can only post-process it. The other option is to see in real-time what is being traced. The 2nd trace option named EventLog just does that. It traces to the system event trace which you can see through the system management console in by running Start->Run->compmgmt.msc. However, a better tool for this job is DebugView  from the erstwhile Sysinternals now acquired by Microsoft. Its free and available from here.

Install this and bring up DbgView.exe. Hit Ctrl+L to bring up the filters dialog (so that you can narrow down and only see your app's log). In the Include text box enter your application's name (note that we put that in the trace messages and hence you can filter on it).

Run the App and DebugView will dynamically show the trace messages as the app traces them.