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.
Comments
Anonymous
June 06, 2007
Great post!If the app they are doing is ASP.NET 2.0 then HealthMonitoring that ships with ASP.NET 2.0 is thier friend, i've noticed that folks overlook it toohttp://blogs.msdn.com/alikl/archive/2007/05/02/asp-net-health-monitoring-means-logging-and-auditing.aspxaliklAnonymous
June 20, 2007
Even though everyone knows about break-points, trace points seem to have been used way less. DevelopersAnonymous
July 24, 2007
Hello Sir, I have a problem with Trace, When I put my Trace wrapper class in a seprate dll, it can not read app.config of exe file which run it. any idea? Thanks for your helpAnonymous
July 26, 2007
I'm not too sure about the app.config issue, but there is an easy workaround. Use some static (be careful to handle multi-threading) member to set the level from your exe.Anonymous
August 18, 2007
It would be much more efficient to move the 'if' statement from the inner Error/Info methods to the outer Error/Info methods. If the inner condition is false, then there was no need to make the call in the first place and as such, no call to String.Format either.Anonymous
September 17, 2007
myspace funny comments graphicsAnonymous
September 21, 2007
The comment has been removedAnonymous
September 28, 2007
Log4net is cool! hopefully they will come up with new version using Orcas ...Anonymous
January 01, 2008
There is actually no need for the overloaded methods. If you use params as an argument, you can pass zero arguments as well. This means you can remove two of the four methods and, thereby, also resolving the issue with the string.Format() being called unnecessarily if tracing is set to false.Anonymous
January 01, 2008
Using params indiscriminately is a bad idea as it reduces readability for the user. E.g. if I have a params, how do I convery that the first is the format string and then others are the args to it. Why do you think the BCL defines such overloads instead of using params. The perf implication is trivial in front of the readability benefits. If perf is important build with the conditional attribute off and C# compiler will NOP all calls to the TRACE methodsAnonymous
November 24, 2008
Error 4 The name 'Thread' does not exist in the current context C:Documents and Settingsic011057My DocumentsVisual Studio 2008ProjectsConsoleApplication4ConsoleApplication4Class1.cs 52 Error 2 The name 'CultureInfo' does not exist in the current context C:Documents and Settingsic011057My DocumentsVisual Studio 2008ProjectsConsoleApplication4ConsoleApplication4Class1.cs 27 these are errors i am gettingAnonymous
October 16, 2012
completely unaware of the awesome trace library. Things that crash above 128 Mb are not awesome but bad codeing !