Click here to Skip to main content
15,867,453 members
Articles / Web Development / ASP.NET

BaseLib.Tracer: Tracing Done Right

Rate me:
Please Sign up or sign in to vote.
4.30/5 (10 votes)
31 Mar 2023Public Domain9 min read 30K   24   24
Near real time, multi threading safe tracing for any .NET technology
Most programs need a way to collect errors, exceptions and other information, like what happened before an exception occurred. Collecting this information is called tracing. DotNet has some tracing functionality, but it is much too slow. Having tracing active should not slow down the application, which can be achieved by writing the tracing information first in RAM and process it later on a different thread.

Content

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.)

BaseLib.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.

Design overview

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 four kinds of tracing messages, depending on which tracing method is called:

  • Tracer.Trace()
  • Tracer.TraceWarning()
  • Tracer.TraceError()
  • Tracer.TraceException()

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.

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

Tracer.TraceException() 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:

C#
Tracer.Trace("Application started");

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

Tracer.Trace("Start Connect DB");
try {
  ConnectDB();
  Tracer.Trace("DB connected");
} catch (Exception ex) {
  Tracer.TraceException(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:

C#
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",
  fileExtension: "log"
  maxFileByteCount: 10*1000*1000,
  maxFileCount: 5,
  logFileWriterTimerInitialDelay: 1000, //msec
  logFileWriterTimerInterval: 10*1000 //msec
  newFileCreated,
  filter);

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. newFileCreated is a method that gets called when a new log file gets created. filter is a method that gets called whenever a message should get written to the log file. If it returns true, that particular message will not get written to the log file.

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

Normally, the debugger breaks after an exception is thrown and stops where the catch statement is. By that time, the local data is lost where the exception was thrown. Use Tracer.Exception() to address this:

C#
//an error was detected
throw Tracer.Exception(new MyException("Some info"));

Tracer.Exception() will break in the debugger and the data causing the exception to be thrown is still available. The developer can then let the degugger continue to run and the exception gets thrown. The developer can control during runtime with IsBreakOnException if the break should happen or not.

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.TraceException(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.

Often, it would be interesting to know what the user did before the exception was thrown. Storing all major user interactions with the application would generate too much information. But when using Tracer, the information gets only written into RAM and overwritten after some time. If an exception gets thrown, it is possible to get the messages traced before the exception and add them to the exception, which then might get written to a log file.

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.

Moving ACoreLib from CodePlex to BaseLib on Github

The original article was written for ACoreLib which I shared on CodePlex.com. Unfortunately, Microsoft shut this website down and I don't have the source code for ACoreLib anymore, because I kept adding new code and renamed the library BaseLib, which I share on GitHub.com. The functionality is still the same, but some names have changed. I updated the article using the new names.

Download Code

The code for this article is in BaseLib/Tracer.cs.

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

License

This article, along with any associated source code and files, is licensed under A Public Domain dedication


Written By
Software Developer (Senior)
Singapore Singapore
Retired SW Developer from Switzerland living in Singapore

Interested in WPF projects.

Comments and Discussions

 
QuestionBug in Program.cs Pin
DataObjx5-Apr-23 5:51
DataObjx5-Apr-23 5:51 
AnswerRe: Bug in Program.cs Pin
Peter Huber SG18-Apr-23 0:56
mvaPeter Huber SG18-Apr-23 0:56 
QuestionSource Code not available? Pin
Member 101955058-Feb-23 3:19
professionalMember 101955058-Feb-23 3:19 
AnswerRe: Source Code not available? Pin
Peter Huber SG31-Mar-23 1:18
mvaPeter Huber SG31-Mar-23 1:18 
QuestionPlease provide a local copy of your code Pin
Pete O'Hanlon16-Feb-17 21:25
subeditorPete O'Hanlon16-Feb-17 21:25 
PraiseWill try it out. Pin
Allister Beharry20-Oct-16 10:05
Allister Beharry20-Oct-16 10:05 
GeneralRe: Will try it out. Pin
Peter Huber SG20-Oct-16 20:21
mvaPeter Huber SG20-Oct-16 20:21 
QuestionHow it is different from log4net/nlog/serilog? Pin
ignatandrei20-Oct-16 2:23
professionalignatandrei20-Oct-16 2:23 
AnswerRe: How it is different from log4net/nlog/serilog? Pin
Peter Huber SG20-Oct-16 6:01
mvaPeter Huber SG20-Oct-16 6:01 
GeneralRe: How it is different from log4net/nlog/serilog? Pin
ignatandrei21-Oct-16 0:14
professionalignatandrei21-Oct-16 0:14 
GeneralRe: How it is different from log4net/nlog/serilog? Pin
Peter Huber SG22-Oct-16 11:04
mvaPeter Huber SG22-Oct-16 11:04 
SuggestionLogging to database Pin
Casper the Friendly Ghost19-Oct-16 23:46
Casper the Friendly Ghost19-Oct-16 23:46 
GeneralRe: Logging to database Pin
Peter Huber SG20-Oct-16 6:08
mvaPeter Huber SG20-Oct-16 6:08 
GeneralRe: Logging to database Pin
ignatandrei23-Oct-16 7:48
professionalignatandrei23-Oct-16 7:48 
GeneralRe: Logging to database Pin
Peter Huber SG17-Nov-16 17:49
mvaPeter Huber SG17-Nov-16 17:49 
QuestionIt looks interesting... Pin
Garth J Lancaster19-Oct-16 15:15
professionalGarth J Lancaster19-Oct-16 15:15 
AnswerRe: It looks interesting... Pin
Peter Huber SG20-Oct-16 6:29
mvaPeter Huber SG20-Oct-16 6:29 
AnswerRe: It looks interesting... Pin
Peter Huber SG22-Oct-16 11:07
mvaPeter Huber SG22-Oct-16 11:07 
AnswerRe: It looks interesting... Pin
SteveHolle16-Feb-17 4:25
SteveHolle16-Feb-17 4:25 
GeneralRe: It looks interesting... Pin
Garth J Lancaster16-Feb-17 16:42
professionalGarth J Lancaster16-Feb-17 16:42 
GeneralRe: It looks interesting... Pin
Pete O'Hanlon16-Feb-17 21:21
subeditorPete O'Hanlon16-Feb-17 21:21 
GeneralRe: It looks interesting... Pin
Garth J Lancaster16-Feb-17 22:03
professionalGarth J Lancaster16-Feb-17 22:03 
GeneralRe: It looks interesting... Pin
SteveHolle17-Feb-17 5:26
SteveHolle17-Feb-17 5:26 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Praise Praise    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.