Introduction
The objective of this article is to show how easy it is to get information from your running application and how you could store the same in a destination of your choice with very little development, making it easier for you to query available information and assist in diagnosing live system issues. We will start with basic understanding of Tracing with an example and then move on to the concept of advanced tracing.
Tracing provides a way to instrument your running application. It helps you trace code execution and you can emit information from your code during execution. Let us try to build a small application to understand the benefits of tracing. The two most important classes of concern to us from application code perspective is Debug and Trace, both are in System.Diagnostics namespace
, the former is mainly for debug build and the latter for release build of your application.
To understand tracing in .NET Framework, let’s use the most basic application which greets user, every programmer’s favorite, Hello World!
using System;
using System.Diagnostics;
public class BasicTracingSample
{
public static void Main()
{
Trace.WriteLine("Program execution started...");
Console.WriteLine("Enter your name :");
string strName = Console.ReadLine();
Console.WriteLine(string.Format("Hello {0}!", strName));
Trace.WriteLine(string.Format("Greeted User {0}", strName));
Trace.WriteLine("Program finished...");
Console.ReadLine();
}
}
And let’s define the tracing settings for the above program using application configuration file as follows:
Compile the above application and execute it using the following commands:
Note that you have to define the TRACE constant as part of compilation for tracing to work. When working with projects in Visual Studio, you can achieve this using project property page under Build tab as follows:
Let’s now execute the application. You would notice that as part of the execution, it has created a log file with the following contents:
In summary, using application configuration file and Trace.WriteLine
method calls in code, we were able to get information from executing application to a log file. In our case, information was logged to a log file because we chose the TextWriterTraceListener
. If we use EventLogTraceListener
provided by .NET Framework, it would start logging to windows event viewer. So you can choose your own logging destination by selecting trace listeners provided by .NET Framework.
Trace Methods
Trace class offers the following methods which can be used for emitting information during application execution:
Write
WriteLine
TraceInformation
TraceWarning
TraceError
These methods are tracing framework API for your application to simply call a relevant Trace
method and the configured TraceListener
would take care of dumping information to its known destination. These different methods help in determining the type of trace and additional information for that type so that trace listener can accordingly log it. For example, in case of EventLogTraceListener
, it will log the type, i.e. information, warning, or error as a value in "Type
" column so that you can easily filter on it. It is basically for the trace listener implementation class to make best use of the information passed to it. These methods also use the trace switch defined for the trace listener in determining whether to log the trace. Let’s understand trace switches.
Trace Switches
The following table defines possible trace switches and how they affect trace output:
Enumerated value | Integer value | Type of message displayed (or written to a specified output target) |
Off | 0 | None |
Error | 1 | Only error messages |
Warning | 2 | Warning messages and error messages |
Info | 3 | Informational messages, warning messages, and error messages |
Verbose | 4 | Verbose messages, informational messages, warning messages, and error messages |
Source: http://msdn.microsoft.com/en-us/library/aa983740(v=vs.71).aspx
Trace switch gives you further ability to filter for only relevant information that you are interested in. During different stages of an application, you may want to switch between different switch values to control the output. For example, when a new application goes live for the first time, you may want to set the trace switch as Verbose so that you capture all the information but once the application has been stable for some time and you are not interested in logging all the information coming out of your application, then you may set the trace switch as Warning, and so on. And the best part of it is that you can configure all this with application configuration file changes and you don’t need to recompile your application.
Need Something More
So far so good, but we need something more! You have a choice of using listeners available as part of .NET Framework such as ConsoleTraceListener
, TextWriterTraceListener
, EventLogTraceListener
, XmlWriterTraceListener
and so on. All these existing trace listeners are very good for some small application but for a large distributed application, you need a more robust approach for collecting and processing information (*making any good out of it*) from your executing application. Trace listeners provided by .NET framework log to destinations which are not ideal for most distributed applications as functionality is spread across multiple applications, several components running on different servers across server estate and your application is logging large amount of information, which mostly is the case in a large distributed application. It becomes very difficult to search for information in a text file or event viewer, or group related information. Let’s take the most common requirement, say you want to search all the information logged for a particular transaction based on the transaction number or some other identifier for it. It would not be easy to extract such information from a text file or event viewer as the information that you are looking for would be scattered throughout the file/event viewer making it difficult to extract the real information you need.
To add to the woes, you need to work out your own approach for maintaining these destinations such as periodically moving the log files to some backup store and so on. Basically, we need a tracing solution which:
- Supports logging all the information from multiple applications to a central destination
- Provides the ability to query the information in a simple manner as a database table (select, filter, sort, group, and so on)
- Provides an easy approach for maintenance of the logging destination
When I thought of such requirements for tracing solution, the immediate response was logging to a database table. If we are able to log trace information from an application to a database table, then it meets all of the above requirements.
Custom Trace Listener to Rescue!
And a custom trace listener comes to the rescue! Tracing offers a pluggable framework for .NET applications to log information during execution. By pluggable, I mean you can add your custom trace listeners and provide your custom implementation of where you want to log the information and how. For example, you can write a custom trace listener to dump information to a table in database.
There are few major advantages of using a database table as logging destination, such as:
- It provides the ability to use all DBMS constructs to query, filter, and summarize the information available. It is as good as any other transaction table and you can use the information available in the best possible manner.
- Maintenance becomes much easier with DB tables such that you can delete rows with unwanted information by simply writing a query. You can easily identify rows with unwanted data and delete these selectively. Alternatively, you can also schedule a DB job which deletes information more than 3 months old, etc. And many similar possible approaches as you would otherwise use with a database table.
There are some disadvantages of using a database table as logging destination and hence, it would not be a recommended approach if:
- Your application is emitting a LOT of information in a very short span of time as it would cause lot of database hits in very quick succession and may affect database performance, network bandwidth, and in turn, your application performance.
- There is any kind of latency involved in accessing database such as network latency as it could be overburdening an already slow network and result in underutilization of network resources for core business purpose and could affect overall performance of your application and network.
You should measure performance of your application with respect to database and consider the above factors before deciding to use database table as a destination for tracing. Also, since you can use multiple trace listeners for your application, you can decide to switch between these available trace listeners as and when required and make the best use of their features for diagnosing the issue and you don’t need to recompile your application either. You can control the trace listeners for application from the configuration file itself but for certain types of applications, you may need to restart the application for trace listener changes in configuration file to take effect.
Let’s move on to start designing a custom database trace listener and then its implementation.
Design Considerations
Let’s design the table in which we will log all our trace entries:
tracelog |
PK | traceid | int | identity |
message | xml | |
type | varchar | Default 'Verbose' |
componentname | varchar | Default NULL |
loggeddate | datetime | Default getdate() |
Let’s highlight key requirements that this custom DB trace listener should support:
- To be able to categorize the information coming from application properly instead of dumping it all as part of a long
string
(and you are not sure where one part ends and other begins as your eye ball takes effort to scan it slowly). We need something like XML tree where each element represents certain information which can be easily identified and searched upon.
We define the data type of the message column in our table as XML and trace listener implementation to take care of converting the information coming its way into an XML string
- To be able to define connection string for the database in configuration file.
This can be defined as part of initializeData
attribute already supported on trace listener in application configuration file and we would be supporting an additional attribute for this purpose as well namely connectionString
.
- It should provide the ability to assign an identifier at application/service level to trace entries so that you can filter/group entries from one same application.
Trace listener implementation would support an additional attribute, namely componentName
which can be defined in the application configuration file to separately identify all the trace entries from an application. The value defined for this attribute would be stored in the componentname
column in table.
- Ability to switch tracing level without the need to restart application (such as in case of Windows services).
Trace listener implementation would support an additional attribute, namely refreshTraceConfig
of type boolean to decide whether tracing needs to refresh the trace switch value.
- If there are any errors during the execution of custom trace listener, these should be logged to a text file separately.
Custom Database Trace Listener Implementation
Let’s understand how we have achieved the goals set forward for us by looking at the actual code. Find below the entire source code for the custom trace listener which uses a database table as its destination:
using System;
using System.Data;
using System.Data.SqlClient;
using System.Diagnostics;
using System.IO;
using System.Xml.Linq;
using System.Threading;
using System.Linq;
namespace AdvancedTracing
{
internal delegate void LogIt(string message, string type, string componentName);
public delegate void DBTraceFailedHandler (string exceptionText);
public class DBTraceListener : TraceListener
{
public event DBTraceFailedHandler DBTraceFailed;
#region Constants
private const string STORED_PROC_NAME = "prc_writetraceentry";
private const string STORED_PROC_MESSAGE_PARAM_NAME = "@message";
private const string STORED_PROC_MESSAGETYPE_PARAM_NAME = "@type";
private const string STORED_PROC_COMPONENTNAME_PARAM_NAME = "@componentname";
private const string TRACE_SWITCH_NAME = "DBTraceSwitch";
private const string TRACE_SWITCH_DESCRIPTION =
"Trace switch defined in config file for configuring trace output to database";
private static readonly string DEFAULT_TRACE_TYPE = "Verbose";
#endregion
#region Class Data
private SqlConnection _cn;
private SqlCommand _cm;
private string _connectionString;
private bool _disposed = false;
private TraceSwitch TraceSwitch =
new TraceSwitch(TRACE_SWITCH_NAME, TRACE_SWITCH_DESCRIPTION, DEFAULT_TRACE_TYPE);
private LogIt workerMethod;
private string _componentName;
private object _traceLockObject = new object();
private object _fileLockObject = new object();
private Timer _traceSwitchTimer;
private bool _refreshTraceConfig = false;
#endregion
#region Properties
public override bool IsThreadSafe
{
get { return false; }
}
public string ConnectionString
{
get
{
if ( string.IsNullOrEmpty(this._connectionString))
{
this.LoadAttributes();
}
return this._connectionString;
}
set { this._connectionString = value; }
}
public string ComponentName
{
get
{
if (string.IsNullOrEmpty(this._componentName))
{
this.LoadAttributes();
}
return this._componentName;
}
set { this._componentName = value; }
}
public bool RefreshTraceConfig
{
get
{
this.LoadAttributes();
return this._refreshTraceConfig;
}
set
{
if (value)
{
if (!this._refreshTraceConfig)
{
this._refreshTraceConfig = true;
this._traceSwitchTimer = new Timer(new TimerCallback(RefreshSwitch),
null, new TimeSpan(0, 15, 0), new TimeSpan(0, 15, 0));
}
}
else
{
this._refreshTraceConfig = false;
this._traceSwitchTimer.Dispose();
this._traceSwitchTimer = null;
}
}
}
#endregion
#region Methods
void RefreshSwitch(object o)
{
try
{
if (this.RefreshTraceConfig)
{
Trace.Refresh();
}
}
catch(Exception ex)
{
this.WriteLine(
string.Format("Trace.Refresh failed with following exception: {0}, ", ex.ToString()),
"Error",
"DBTraceListener"
);
this.WriteEntryToInternalLog(string.Format
("Trace.Refresh failed with following exception: {0}, ", ex.ToString()));
}
}
private void WriteEntryToInternalLog(string msg)
{
lock (this._fileLockObject)
{
try
{
File.AppendAllText(AppDomain.CurrentDomain.BaseDirectory + @"\DBTraceListener.log",
string.Format("{0}{1}: {2}", Environment.NewLine, DateTime.Now.ToString(), msg));
}
catch
{
}
}
}
public bool TestDBConnection()
{
try
{
using (SqlConnection cn = new SqlConnection(this.ConnectionString))
{
cn.Open();
}
return true;
}
catch
{
return false;
}
}
internal bool ShouldLogTrace(TraceEventType eventType)
{
bool shouldLog = true;
switch (eventType)
{
case TraceEventType.Critical:
case TraceEventType.Error:
shouldLog = this.TraceSwitch.TraceError;
break;
case TraceEventType.Warning:
shouldLog = this.TraceSwitch.TraceWarning;
break;
case TraceEventType.Information:
shouldLog = this.TraceSwitch.TraceInfo;
break;
case TraceEventType.Start:
case TraceEventType.Stop:
case TraceEventType.Suspend:
case TraceEventType.Resume:
case TraceEventType.Transfer:
case TraceEventType.Verbose:
shouldLog = this.TraceSwitch.TraceVerbose;
break;
}
return shouldLog;
}
#region TraceEvent
public override void TraceEvent(TraceEventCache eventCache,
string source, TraceEventType eventType, int id)
{
this.TraceEvent(eventCache, source, eventType, id, string.Empty);
}
public override void TraceEvent(TraceEventCache eventCache,
string source, TraceEventType eventType, int id, string message)
{
XElement msg;
try
{
if (!this.ShouldLogTrace(eventType))
return;
if (eventType == TraceEventType.Critical ||
eventType == TraceEventType.Error ||
eventType == TraceEventType.Warning)
{
msg = new XElement("TraceLog",
new XElement("Message", message),
new XElement("Id", id),
new XElement("CallStack", eventCache.Callstack.ToString()),
new XElement("ThreadId", eventCache.ThreadId),
new XElement("ProcessId", eventCache.ProcessId)
);
}
else
{
msg = new XElement("TraceLog",
new XElement("Message", message));
}
this.WriteLineInternal(msg.ToString(), eventType.ToString(), null);
}
catch(Exception ex)
{
this.WriteLine(
string.Format("AdvancedTracing::DBTraceListener - Trace.TraceEvent failed
with following exception: {0}, for message {1} ", ex.ToString(), message),
"Error",
"DBTraceListener"
);
this.WriteEntryToInternalLog(string.Format("Trace.TraceEvent failed
with following exception: {0}", ex.ToString()));
}
}
public override void TraceEvent(TraceEventCache eventCache, string source,
TraceEventType eventType, int id, string format, params object[] args)
{
XElement msg;
try
{
if (!this.ShouldLogTrace(eventType))
return;
if (eventType == TraceEventType.Critical ||
eventType == TraceEventType.Error ||
eventType == TraceEventType.Warning)
{
msg = new XElement("TraceLog",
new XElement("Message", string.Format(format, args)),
new XElement("Id", id),
new XElement("CallStack", eventCache.Callstack.ToString()),
new XElement("ThreadId", eventCache.ThreadId),
new XElement("ProcessId", eventCache.ProcessId)
);
}
else
{
msg = new XElement("TraceLog",
new XElement("Message", string.Format(format, args)));
}
this.WriteLineInternal(msg.ToString(), eventType.ToString(), null);
}
catch (Exception ex)
{
this.WriteLine(
string.Format("AdvancedTracing::DBTraceListener - Trace.TraceEvent failed
with following exception: {0}, for message {1}", ex.ToString(), format),
"Error",
"DBTraceListener"
);
this.WriteEntryToInternalLog(string.Format("Trace.TraceEvent failed with
following exception: {0}", ex.ToString()));
}
}
#endregion
#region TraceTransfer
public override void TraceTransfer(TraceEventCache eventCache, string source,
int id, string message, Guid relatedActivityId)
{
try
{
if (this.ShouldLogTrace(TraceEventType.Transfer))
{
XElement msg = new XElement("TraceLog",
new XElement("Message", message),
new XElement("Source", source),
new XElement("Id", id),
new XElement("RelatedActivityId", relatedActivityId.ToString()),
new XElement("CallStack", eventCache.Callstack.ToString()),
new XElement("ThreadId", eventCache.ThreadId),
new XElement("ProcessId", eventCache.ProcessId));
this.WriteLine(msg.ToString(), TraceEventType.Verbose.ToString(), null);
}
}
catch (Exception ex)
{
this.WriteLine(
string.Format("AdvancedTracing::DBTraceListener - Trace.TraceTransfer failed
with following exception: {0}, for message {1} ", ex.ToString(), message),
"Error",
"DBTraceListener"
);
this.WriteEntryToInternalLog(string.Format("Trace.TraceTransfer failed with
following exception: {0}", ex.ToString()));
}
}
#endregion
public override string ToString()
{
return string.Format("DBTraceListener for Component: {0} using ConnectionString: {1}",
this.ComponentName, this.ConnectionString);
}
#region Write Methods
public override void Write(object o)
{
if (o != null)
{
this.WriteLine(o.ToString(), null);
}
}
public override void Write(string message)
{
this.WriteLine(message, null);
}
public override void Write(object o, string category)
{
if (o != null)
{
this.WriteLine(o.ToString(), category);
}
}
public override void Write(string message, string category)
{
this.WriteLine(message, category);
}
#endregion
#region WriteLine Methods
public override void WriteLine(object o)
{
if (o != null)
{
this.WriteLine(o.ToString(), null);
}
}
public override void WriteLine(object o, string category)
{
if (o != null)
{
this.WriteLine(o.ToString(), category);
}
}
public override void WriteLine(string message)
{
this.WriteLine(message, null);
}
override public void WriteLine(string message, string category)
{
try
{
if (!this.ShouldLogTrace(TraceEventType.Verbose))
return;
XElement msg = new XElement("TraceLog",
new XElement("Message", message));
this.WriteLineInternal(msg.ToString(), category, null);
}
catch (Exception ex)
{
this.WriteEntryToInternalLog(string.Format
("WriteLine failed with following exception: {0}", ex.ToString()));
}
}
public void WriteLine(string message, string category, string componentName)
{
try
{
if (!this.ShouldLogTrace(TraceEventType.Verbose))
return;
XElement msg = new XElement("TraceLog",
new XElement("Message", message));
this.WriteLineInternal(msg.ToString(), category, componentName);
}
catch (Exception ex)
{
this.WriteEntryToInternalLog(string.Format
("WriteLine failed with following exception: {0}", ex.ToString()));
}
}
#endregion
private void WriteLineInternal(string message, string category, string componentName)
{
workerMethod = SaveLogEntry;
workerMethod.BeginInvoke(message, category, componentName, null, null);
}
private void SaveLogEntry(string message, string category, string componentName)
{
lock (_traceLockObject)
{
try
{
if (this._cn.State == ConnectionState.Broken ||
this._cn.State == ConnectionState.Closed)
{
this._cn.ConnectionString = this.ConnectionString;
this._cn.Open();
}
this._cm.Parameters[STORED_PROC_MESSAGE_PARAM_NAME].Value = message;
this._cm.Parameters[STORED_PROC_MESSAGETYPE_PARAM_NAME].Value = category;
if (string.IsNullOrEmpty(componentName))
{
if (string.IsNullOrEmpty(this.ComponentName))
{
this._cm.Parameters[STORED_PROC_COMPONENTNAME_PARAM_NAME].Value =
DBNull.Value;
}
else
{
this._cm.Parameters[STORED_PROC_COMPONENTNAME_PARAM_NAME].Value =
this.ComponentName;
}
}
else
{
this._cm.Parameters[STORED_PROC_COMPONENTNAME_PARAM_NAME].Value = componentName;
}
this._cm.ExecuteNonQuery();
}
catch (Exception ex)
{
if (this.DBTraceFailed != null)
{
DBTraceFailed(ex.ToString());
}
this.WriteEntryToInternalLog(ex.ToString());
}
finally
{
}
}
}
protected override string[] GetSupportedAttributes()
{
return new string[] { "connectionString", "componentName", "refreshTraceConfig" };
}
private void LoadAttributes()
{
if (Attributes.ContainsKey("connectionString"))
{
this.ConnectionString = this.Attributes["connectionString"];
}
if (Attributes.ContainsKey("componentName"))
{
this.ComponentName = this.Attributes["componentName"];
}
if (Attributes.ContainsKey("refreshTraceConfig"))
{
bool val;
bool.TryParse(this.Attributes["refreshTraceConfig"], out val);
this.RefreshTraceConfig = val;
}
}
protected override void Dispose(bool disposing)
{
if (!this._disposed)
{
if (disposing)
{
if (this._cn != null)
this._cn.Dispose();
if (this._cm != null)
this._cm.Dispose();
if (this._traceSwitchTimer != null)
this._traceSwitchTimer.Dispose();
}
this._disposed = true;
}
this._cm = null;
this._cn = null;
base.Dispose(disposing);
}
#endregion
#region Constructors
public DBTraceListener() : this(string.Empty) { }
public DBTraceListener(string initializeData)
: base(initializeData)
{
this._cn = new SqlConnection();
this._cn.ConnectionString = initializeData;
this.ConnectionString = initializeData;
try
{
this._cn.Open();
}
catch(Exception ex)
{
this.WriteEntryToInternalLog(string.Format("Could not connect to database from
the provided connection string. Exception: {0}", ex.ToString()));
throw;
}
this._cm = this._cn.CreateCommand();
this._cm.CommandText = STORED_PROC_NAME;
this._cm.CommandType = CommandType.StoredProcedure;
this._cm.Parameters.Add(new SqlParameter(STORED_PROC_MESSAGE_PARAM_NAME, DBNull.Value));
this._cm.Parameters.Add(new SqlParameter(STORED_PROC_MESSAGETYPE_PARAM_NAME, DBNull.Value));
this._cm.Parameters.Add(new SqlParameter
(STORED_PROC_COMPONENTNAME_PARAM_NAME, DBNull.Value));
}
#endregion
}
}
The above piece of code is what you need for a custom database trace listener. You need to run additional database scripts to create the table and stored procedure required for this, the scripts for the same are as follows:
if exists (select * from sys.tables where [name]='tracelog')
begin
print 'table tracelog already exists.'
end
else
begin
print 'creating table tracelog...'
create table [dbo].[tracelog](
[traceid] [bigint] identity(1,1) not null,
[message] [xml] null,
[type] [varchar](20) null default ('Verbose'),
[componentname] [varchar](200) null default (null),
[loggeddate] [datetime] null default (getdate()),
primary key clustered
(
[traceid] asc
)with (ignore_dup_key = off) on [primary]
) on [primary]
print 'table tracelog created.';
end
go
if exists (select * from sys.objects where object_id = object_id(N'[dbo].[prc_writetraceentry]') _
and type in (N'p', N'pc'))
drop procedure [dbo].[prc_writetraceentry]
go
create proc prc_writetraceentry
@message xml = null,
@type varchar(100) = 'Verbose',
@componentname varchar(200) = null
as
begin
insert tracelog([message], type, componentname)
values(@message, @type, @componentname)
end
go
create nonclustered index [idx_tracelog_loggeddate] on [dbo].[tracelog]
(
[loggeddate] desc,
[componentname] asc,
[traceid] asc
)
go
Now, let’s modify the application configuration file and add the newly created trace listener. You need to add the trace listener as follows:
And execute the application and you would see the following in tracelog
table in database:
In summary, salient features of custom db trace listener are as follows:
- Writes trace entries to database table as XML data
- Provides additional column to identify entries with the source application/component
- Writes to a text file the errors generated within DB trace listener implementation
In some future post (I don’t like to say next post as I might write about something completely different in my next post), we would try to look at advanced tracing techniques such as code injection to inject code into assembly which would log additional information at the start of each method execution so that you can trace each method as it executes in your application.
Happy coding!!
Vande Mataram!
(A salute to motherland)
P.S. In addition to blogging, I use Twitter to share tips, links, etc. My Twitter handle is: @girishjjain