Monday, 7 October 2013

Simple TraceListener example

One VERY common thing that we need to do in live sites is to "log" or "trace" information from the application so that we can debug things such as timings, return values or whatever else we need to look at. Often, these are not easy or possible to obtain in test systems which don't usually have the same deployment model, the same loads and the same number of users.

In .Net, they have a system that is based on something called Trace Listeners. It is very powerful and flexible in as much as you can trace different sources and redirect these sources to the same or different "log locations" such as flat file, XML, database or even Azure and other customer event logs.

The problem is that the basic examples are either too complicated or non existent so here is the basic setup required to get tracing working.

The main types you need are in the System.Diagnostics namespace which is in System.dll which is useful because virtually all applications will reference this and it will be available on all .Net deployments.

As with anything that is complicated/powerful, I HIGHLY recommend that you start with the example here and then change parts of it to suit your application. I have a habit of using a basic example and changing everything while I implement it which leads to painful debugging!

Firstly, add the correct configuration to your web/app.config so that anything that is traced is logged somewhere. I usually put this right at the bottom of the config so it is easy to find (it lives under the top-level Configuration element). One of the easiest ways to test this example is to log to an xml file as below:

<system.diagnostics>
    <switches>
      <add name="Default" value="Info"/>
    </switches>
    <trace autoflush="true" indentsize="4">
      <listeners>
        <add name="xmlListener"
          type="System.Diagnostics.XmlWriterTraceListener"
          initializeData="c:\logs\admintrace.xml" traceOutputOptions="ProcessId, DateTime" />
        <remove name="Default" />
      </listeners>
    </trace>
  </system.diagnostics>

Note that the Value of the switch must match one of the predefined values Error, Info, Off, Verbose, Warning. I think it can be a comma-separated list of more than one of these but don't take my word for it! The location of the file is the value of initializeData. Also, autoflush=true will reduce the performance slightly but will make your messages get written to file immediately. On a live system, you might want to leave this set to false and have it move data out in efficient size blocks.

Then, all you need to do is call static methods on the Trace class in your code like this:

Trace.TraceInformation("GetUserData duration(ms) " + stopWatch.ElapsedMilliseconds.ToString());

That's it! There are other methods like TraceError and TraceWarning which you can use but note that these will need to match the switch value (or be a higher level that the switch value) or otherwise they will not appear in the log. For instance, if the switch is set to Error, then warnings and info won't be logged. If you set it to Info, then info, errors and warnings will be logged.

Verbose is the most information traced but this might cause too much noise in your application in which case you will need to look at Trace sources and separating the trace calls into separate log files (this is done by namespaces). Also, note that as with all IO, this adds a load and fills up disk space in your application so try and avoid tracing too much information, you can always switch it to "Off" at run-time and it will stop logging.
Post a Comment