Simple logging with use of System.Diagnostic.Trace

By Mirek on (tags: logging, Trace, tracing, categories: code)

Recently we have decided to replace the logging framework we used, because of its not necessary complexity and a bunch of features we did not use and even did not know anything about. The goal was to use the built in System.Diagnostic.Trace facility and cover some of basic requirements we had.

Basically, all we need the logging thing should do is to properly log error with all related information, log additional information and debug information when necessary and to be easily configurable. The .net framework’s build in tracing is based on the Trace class and a collection of trace listeners. Trace class is a kind of an interface between application and the collection of logging output formats. Static class Trace expose methods which can be used to log errors, warnings and other messages. Those messages are then queued and, when the Trace is flushed, sent to all attached listeners.
The trace listener is a receiver of a trace messages which does what ever we want with the received messages.

To achieve our goal we need a trace listener that will write tracing messages to a text file. Fortunately there is one built in TextWriterTraceListener which fits great. All we need is to configure the tracing in our application config file.

<system.diagnostics>
  <trace autoflush="true">
    <listeners>
      <add name="textLogListener" type="System.Diagnostics.TextWriterTraceListener"
           initializeData="myapp.log"  />
      <remove name="Default" />
    </listeners>
  </trace>
</system.diagnostics>

Above configuration section system.diagnostic is a place where we can configure all stuff related to tracing. Here we defined an log file myapp.log where all messages will be written. Auto flush parameter indicates that every message will be immediately saved to log file.
Now since Trace class expose kind of generic methods like Write, WriteLine and so on, we can try to wrap it to have more useful methods.

 

public static class Log
{
      private static string logTimeFormat = "HH:mm:ss.fff";
 
      private static TraceSwitch globalTraceSwitch;
 
      static Log()
      {
          globalTraceSwitch = new TraceSwitch("TraceLevelSwitch", "Global trace level switch");
          Trace.WriteLine(string.Format("#Logging started at {0}", DateTime.Now.ToString()));
      }
 
      private static string getCallingType()
      {
          return (new StackFrame(2, false).GetMethod()).DeclaringType.ToString();
      }
 
      [...]
 
      public static void Error(string message, Exception ex = null,
                              [CallerMemberName] string sourceMember = "",
                              [CallerFilePath] string sourceFilePath = "",
                              [CallerLineNumber] int sourceLineNumber = 0)
      {
          if (globalTraceSwitch.TraceError)
          {
              StringBuilder sb = new StringBuilder();
              sb.AppendFormat("{0} ERROR: ", DateTime.Now.ToString(logTimeFormat));
              sb.AppendLine(message);
              appendMessageDetails(sb, getCallingType(), sourceMember, sourceFilePath, sourceLineNumber, ex);
              Trace.Write(sb.ToString());
          }
      }
 
      public static void Info(string message)
      {
          Trace.WriteLineIf(globalTraceSwitch.TraceInfo,
              string.Format("{0} INFO: {1}", DateTime.Now.ToString(logTimeFormat), message));
 
      }
 
      public static void Debug(string message)
      {
          Trace.WriteLineIf(globalTraceSwitch.TraceVerbose,
              string.Format("{0} DEBUG: {1}", DateTime.Now.ToString(logTimeFormat), message));
      }
  }

 

Lets look at Error method. It takes the error message and optional exception object and construct a message of it. Then uses a Trace class to write a complete error message to the output. For case of cleanness I skipped the appendMassageDetails method which simply formats and appends the exception object. As you can see we made use of c# 5.0 features CallerMemberName, CallerFilePath and CallerLineNumber which defines a variables automatically filled with caller member, caller source file path and source line number. Personally I feel a lack of similar attribute for getting the caller type, but at his point we handled that traveling stack frame of the current call (method getCallingType()).

One thing I did not yet mention is globalTraceSwitch. TraceSwitch is an object used to control tracing. In our simple solution we use it to decide what level of messages we want to have in the log file. We must create an instance of the switch, provide a name (as above in static constructor) and configure it in config file. As can be seen above we have to explicitly check the state of the switch and decide if the message is logged or not.

<system.diagnostics>
  <trace autoflush="true">
    <listeners>
      <add name="textLogListener" type="System.Diagnostics.TextWriterTraceListener"
           initializeData="myapp.log"  />
      <remove name="Default" />
    </listeners>
  </trace>
  <switches>
    <!-- This switch controls general messages. In order to 
       receive general trace messages change the value to the 
       appropriate level. 
       1: gives error messages, 
       2: gives errors and warnings, 
       3: gives information plus all above,
       4: gives debug trace information plus all above -->
    <add name="TraceLevelSwitch" value="4" />
  </switches>
</system.diagnostics>

Having that in place we can now simply log all we need

Log.Error("This was an error!", new ApplicationException("Some strange fenomenon occured"));
Log.Warning("This is the final warning!");
Log.Info("Some precious information.");
Log.Debug("Debug information shoud be very debug");

and we get this kind of log file

#Logging started at 2012-10-13 23:20:20
23:20:20.720 ERROR: This was an error!
   in: WPFTest.MainWindow.Resulting
   source file: d:\research\WPFTest\WPFTest\MainWindow.xaml.cs(47)
   Original exception: Some strange fenomenon occured
23:20:20.722 WARNING: This is the final warning!
   in: WPFTest.MainWindow.Resulting
   source file: d:\research\WPFTest\WPFTest\MainWindow.xaml.cs(48)
23:20:20.723 INFO: Some precious information.
23:20:20.723 DEBUG: Debug information shoud be very debug

As I mentioned the listeners are attached to the Trace, which means you can have many different outputs. We can attach a EventLogTraceListener to log messages to Windows' event log. We can write our own listener which can do anything we want with the traced data.

 

Thats all, cheers.