ACoreLib.Tracer: Tracing Done Right

Content

• Introduction
• Requirements for Tracing and Error Handling
• Typical use cases
• Tracing a message
• Tracing startup of application
• Setting up Tracing
• Accessing traced messages
• Dealing with exceptions
• Extending trace processing & GUI integration
• Change History
• Download Code

Introduction

In every .NET project, regardless of the technology used, some basic functionality is needed right from the start:

Tracing and how to handle exceptions.

Of course, .NET and Visual Studio provides some tracing functionality, but:

• Unnecessarily difficult to use (Trace, Debug, TraceSource, TraceListener, TraceSource, TraceSwitch, ...)
• Visual Studio tracing is much too slow and blocking, making it useless for multithreaded applications
• Trace processing is run on the calling thread, tracing exceptions give problems to caller

Requirements for Tracing and Error Handling

• Available from the very first line of code (no initial setup necessary)
• Take very little time (around a microsecond)
• Trace processing executed on its own thread
• Tracing running continuously, without causing any storage problems
• Trace message filtering and processing accordingly
• Easy extendable (storing trace in db, send email for certain problems, show some messages in GUI, etc.)

ACoreLib.Tracer writes trace message in a fast buffer. Another thread empties the buffer, processes the trace and finally stores the message in a ring buffer, where the oldest trace messages get overwritten. For debugging and exception investigations, it is usually enough to have just the latest trace messages.

It's configurable to write some trace messages for permanent storage to files and/or to use any custom implemented trace processing.

Typical Use Cases

• Application writes from the very first line of code into the trace what is happening, like which files it tries to open or other resources it tries to access. If the application fails to start, the trace information shows what could be completed successfully and which functionality made the start to fail. This information is very useful if the application runs on a remote machine, where it is difficult to observe, what is going on.
• When an exception occurs, the trace information gets included in the Exception message, showing what happened just before (!) the exception occurred.
• Exception and warning messages get stored in a log file. If the file reaches a certain size, a new log file gets created. If there are too many log files, the oldest gets deleted.
• Exceptions could get emailed to the developers, including the trace.

Tracing a Message

The idea of tracing is to write (debugging) messages to a trace. The trace can then be used to investigate why a certain problem happened, or, more precisely, what the application did just before the problem happened. Tracer differentiates 4 kinds of tracing messages, depending on which tracing method is called:

• Tracer.TraceLine()
• Tracer.WarningLine()
• Tracer.ErrorLine()
• Tracer.Exception()

It is up to the application what the difference between just a trace, warning or error is. Tracer writes them all in the same way into the trace, marking them accordingly. Additionally, the application can for example configure that all messages get stored in RAM, only warning and errors written to a trace file and errors emailed to a development account.

One message can be composed by calling several times Tracer.Trace() and a message closing Tracer.TraceLine(). If several threads call Tracer.Trace() at the same time, for each thread, its own trace message gets created.

Tracer.TraceLineWithFilter() takes additionally to the trace message a text, which later can be used for filtering.

Tracer.Exception() should be used whenever an exception got caught. They are treated by Tracer like any other messages, although all exception details get shown in the trace and if a debugger is attached, it might execute a Break().

Tracing Startup of Application

To use full tracing functionality from the very first line of code executed, Tracer is made a static class.

It might be useful to trace the starting of the application like this:

Tracer.TraceLine("Application started");

Configuration configuration;
Tracer.TraceLine("Read Configuration started");
try {
  configuration = ReadConfiguration();
} catch (Exception ex) {
  Tracer.Exception(ex, "Read Configuration failed, used default configuration");
  configuration  = Configuration .Default;
}
Tracer.TraceLine(configuration.ToString());
Tracer.TraceLine("Read Configuration completed");

Tracer.TraceLine("Start Connect DB");
try {
  ConnectDB();
  Tracer.TraceLine("DB connected");
} catch (Exception ex) {
  Tracer.Exception(ex, "Connect DB failed");
}

Comments

• Very first line writes to trace. Among other things, this is useful to show in the trace when exactly the trace has started.
• For every step needed to setup the application, use its own _try_ statement. If there is an exception, do something else so that the application still can start and display some (error) information.

Setting Up Tracing

The application can configure some tracing functionality:

Tracer.IsTracing = true;
Tracer.IsWarningTracing = true;
Tracer.IsErrorTracing = true;
Tracer.IsExceptionTracing = true;
Tracer.IsBreakOnWarning = false;
Tracer.IsBreakOnError = true;
Tracer.IsBreakOnException = true;

//setup tracing file
TraceLogFileWriter =new TraceLogFileWriter(
  directoryPath: Environment.CurrentDirectory + @"\LogFiles",
  fileName: "FinanceLog",
  maxFileByteCount: 10*1000*1000,
  maxFileCount: 5,
  logFileWriterTimerInitialDelay: 1000, //msec
  logFileWriterTimerInterval: 10*1000); //msec

This code does not need to be right at the beginning of the application, since Tracer can work with its default settings without losing any messages. It's possible to read some (tracing) configuration and trace if there goes anything wrong, even Tracer has not been set up already and then setting up Tracer with the read configuration data.

The IsXxxTracing flags control if a normal message, Warning, Error or Exception gets written in the Tracer RAM buffer or immediately discarded.

The IsBreakOnXxx controls if the debugger should break in an attached debugger if a Xxx type of message gets traced. The developer can change the values of these flags using the debugger, allowing him to control easily how often the debugger will break during debugging.

The constructor of TraceLogFileWriter automatically registers with Tracer.MessagesTraced event. Even the already traced messages will be written to the indicated log file. Once the log file size is bigger than maxFileByteCount, a new file gets created. If more than maxFileCount exists, the oldest files get deleted, to prevent tracing using up all disk space. Setting one of these parameters to 0 will prevent that the corresponding max value gets checked.

Accessing Traced Messages

To get all stored trace messages, just call Tracer.GetTrace(). It returns an array of TraceMessage, sorted by their creation time. During the execution of GetTrace(), no new trace messages get added to guarantee a consistent result. However, they will not get lost, only written after GetTrace() has finished.

Use TraceMessage.ToString() for a simple way to display the trace messages.

Dealing with Exceptions

Throwing Exceptions

It would be good if the debugger would break if the code has detected an illegal condition and throws a new exception. This could be achieved through some VS settings or by setting manually a breakpoint at every throw statement, which is rather cumbersome. 

A better solution is not to use throw statements, but to call Tracer.Thow(new Exception()), which will throw the exception instead. If a debugger is attached and IsBreakOnException is true, the debugger breaks and the exception to be thrown is displayed in the debugger output window. This has the big advantage that the variable content of the throwing method is still available, which makes it much easier to investigate what was the problem. When investigating exceptions only once they are thrown, this data is lost.

Catching Exceptions

Some exceptions might be expected to occur sometimes. If the program should react to the exception by doing something else, the exception should be caught in a try catch statement. The rest of the exceptions should be caught in a central place which is done differently in different .NET technologies:

Technology
Console Application	try catch statement
Windows Form Application	Application.ThreadException
WPF Application	Application.DispatcherUnhandledException
ASP.NET	Global.asax: Application_Error
multi threading	each thread needs its own  try catch statement

Whether an exception is caught locally or globally, it is in both cases a good idea to trace it with Tracer.Exception (exception). This writes the exception with all the exception details to the trace. If a debugger is attached and IsBreakOnException is true, the details also get displayed in the debugger output window.

Extending Trace Processing & GUI Integration

Often, an application needs further processing of trace messages, like displaying warnings, errors and exceptions to the user (GUI), collecting all errors and exceptions in a central database or emailing exceptions to developers. This can be easily done by registering to the event Tracer.MessagesTraced.

Applications with a user interface could provide the following functionality:

• Display and editing of Tracer settings
• Displaying of errors and exceptions to the user. It should be easy to copy the trace information so that it can be sent to support.
• Display of presently stored trace

Change History

Version 1.1: Adding Flushing, i.e., Moving Trace Message from Temporary to Final Buffer on Demand

Every trace message gets temporarily stored in a ringbuffer, so that the thread doing the trace gets hardly delayed (about 1 microsecond). A timer is run on another thread, copying the trace messages every 100 milliseconds to the final trace ringbuffer and calling any listeners of MessagesTraced event for further processing, which can be slow, like writing to a file.

This caused some problems, when for example, the application made a trace and closed immediately. The 100 millisecond timer did not run and no event listener got called. It seemed like the Tracing was not working. A similar problem happened when the trace got inspected after an exception with GetTrace(), because again, the timer did not run yet. For these cases, a Flush() method got added, which forced the timer to run immediately, to move all message from temporary to permanent ring buffer, to call the event listeners and only then to return.

LogFileWriter got a Dispose() method and destructor, which guarantee that when the application gets closed, all trace message get written to the trace file up to the call of these methods. Before, the trace messages of between 0 and 100 milliseconds were missing.

The DotNet framework version got lowered to 4.0.

Breaking Change

TraceMessage[] GetTrace(Action<TraceMessage[]> MessagesTracedHandler) got renamed to

TraceMessage[] AddMessagesTracedListener(Action<TraceMessage[]> MessagesTracedHandler) to better reflect the real purpose of the method.

Download Code

Even I have used Tracer for years and the code runs stable, I will continue to extend the ACoreLib library. To get the latest version, please download it from https://acorelib.codeplex.com.

If you are interested in even faster, non blocking tracing, which is helpful in debugging race conditions, read this article:

• http://www.codeproject.com/Articles/792532/Debugging-multithreaded-code-in-real-time