.NET Instrumentation Workshop
Home About Workshops Articles Writing Talks Books Contact

4. Trace Listeners

As explained on the last page the Trace and Debug classes will deliver trace messages to the objects in the trace listener collection. Trace listener objects are the actual code that stores the data. Trace listeners are not constrained with what they can do with the data, so a trace listener could send the string over a socket to another process, email the string, put the string in a message queue, or put it in a database. The trace listener classes that are provided with the framework are a little less ambitious: they allow you to write the log data via a stream (and hence, to a file), to the event log, to a web page (in an ASP.NET application) or to the system output debug stream.

In this section I will explain how trace listeners work, describe some of the framework trace listeners and explain their shortcomings.

4.1 Framework Trace Listeners

Trace listeners derive from an abstract class called TraceListener a class that implements IDisposable. This class has two abstract methods: the overloads of Write and WriteLine that take a single string. The other overloads are virtual and in the base class are implemented using the abstract methods. Thus, if you intend to write your own trace listener the minimum implementation is to provide overloads of Write and WriteLine that take a single string. However, trace listeners are added to the Listeners collection and are indexed using the Name property, so your custom trace listener should also provide a constructor that calls the protected base class constructor that sets the name. In addition, trace messages are sent to the trace listeners through a TraceListener reference which means that your class's virtual (hence abstract and interface) methods will be called. The following table lists the virtual methods on the TraceListener class.

Virtual Member Description
Close, Dispose If your class holds a resource that implements IDisposable, or uses an unmanaged resource, then you should implement these methods to release those resources.
Fail This is called by Debug.Assert to generate an assert message.
Flush If your class uses a buffered stream then you should implement this to flush the buffer.
GetSupportedAttributes Used by instance trace sources, this returns the names of the attributes that can be used in the configuration file for your class (see trace source attributes)
IsThreadSafe Implement this property if you are sure that your class is thread safe.
Name This returns the name of the trace listener object, in general the default should suffice.
TraceData Trace the value of an object with a footer containing extended information (see instance trace sources)
TraceEvent Used to trace extended information with a footer (see instance trace sources)
TraceTransfer Used by the framework to write extended information with a footer (see instance trace sources)
Write Write data to the underlying storage without an endline
WriteIndent Writes the indent.
WriteLine Write data to the underlying storage with an endline

If you use an instance trace source then one of the TraceEvent methods will be called, these have the same parameters as the TraceEvent methods on the TraceSource class with an additional parameter of type TraceEventCache. The name of this type is a misnomer, it is not a cache of trace events, instead it is further information about the system at the time the event was generated, for example, the time and date, the thread ID and the statck trace. The message that will be generated by the TraceEvent method will be in this form:

<header> <message> <footer>

The <message> is whatever the user traced, the <header> contains the trace source name, the severity of the message and a message identifier. The <footer> can contain information, like the thread ID and the time, from the TraceEventCache object. The TraceEvent methods on the TraceListener class generate the message by calling three methods on the class: WriteHeader, WriteLine and WriteFooter. Although WriteLine is virtual (in fact it is abstract) the other two methods are private methods. This means that you cannot replace them. The default implementation provides a mechanism to restrict the information logged in the footer (trace options), but you are still restricted to the footer implementation provided by TraceListener. If you want to change the header or footer to work in a way that is appropriate to the trace listener you are writing then you'll have to override all of the TraceEvent methods on the TraceListener, but you'll have to replicate the implementation of WriteFooter to take into account any trace options that have been set. I think these methods, TraceHeader and TraceFooter, should have been virtual.

The methods concerned with instance trace sources and asserts will be covered on later pages. The framework provides the following implementations of the TraceListener class:

ClassLogs To
Asserts
InitializeData
ConsoleTraceListener The console Fail messages to the console true means that the output is sent to STDERR
DefaultTraceListener Output debug dtream, Log file Writes the assert message using WriteLine, and if UI asserts are enabled, shows an assert dialog None (AssertUIEnabled and LogFileName are set in <assert>)
DelimitedListTraceListener Log file Writes the assert message using WriteLine Log file name (delimiter attribute used to give delimiter to separate footer items)
EventLogTraceListener NT Event Log Writes the assert message using WriteLine Name of the source in the Application log
FileLogTraceListener Log file Writes the assert message using WriteLine Name of the log file. This class has numerous custom attributes.
TextWriterTraceListener Log File Writes the assert message using WriteLine Log file name
WebPageTraceListener Web page Writes the assert message using WriteLine None
XmlWriterTraceListener Log file Writes the assert message using WriteLine Log file name

Trace listeners can be initialized in two ways. First, you can create an instance in code and add the instance to the Listeners collection. This is the most flexible because you have complete access to the class so you can call any of the class's constructors and access the class's properties. The disadvantage of this mechanism is that you have to know at compile time the trace listeners that you want to use and that all of the trace listeners that you add to the Listeners collection will be called by calls to the Trace (or Debug) class. The second way to initialize listeners is through the application's configuration file, this has the advantage that you can change the trace listeners that are used by changing the settings in the configuration file.

The <system.diagnostics> section has a node called <trace> which is used for all trace listeners (ie it is used for the trace listeners used by the Debug class as well as the Trace class). The <trace> node has two attributes, autoFlush and indentSize, these are used to initialize the AutoFlush and IndentSize static properties on the Trace and Debug classes. The <trace> node contains the <listeners> node which is a collection: child nodes can be added with <add/>, they can be removed with <remove/> and the empty element can be cleared with <clear/>. The <clear/> element invokes a call to Debug.Listeners.Clear, that is, all listeners are removed from the collection and thus after initialization the collection will only contain listeners added after this element. <remove/> allows you to remove a specific trace listener identified by its name through the name attribute. The <add/> element allows you to insert a trace listener into the Listeners collection with a specific name. This element has three attributes: type is the fully qualified type name (that is, it includes the assembly name and the name of the class including the namespace). The documentation says that the name attribute is optional, but it isn't, it is mandatory. This attribute is passed to the Name property of the trace listener and is useful when identifying a trace listener in the Listeners collection. The optional initializeData attribute is data that will be passed to the trace listener constructor with a constructor with a string parameter. The table above indicates how this parameter is used by all the standard framework classes.

There are two important points to make about the table above. The first is that DefaultTraceListener is also initialized using the element system.diagnostics/assert. This element has two attributes, assertuienabled and logfilename which correspond to the AssertUiEnabled and LogFileName properties. AssertUiEnabled determines whether asserts will show a dialog, and LogFileName determines if assert text is written to a file name and if so, the properties has the name of the file. However, note that the log file is also used for trace messages. The other point to make concerns the FileLogTraceListener class. This can be found in the Microsoft.VisualBasic assembly (and in the Microsoft.VisualBasic.Logging namespace) but do not be put off by this, the class is actually rather good. In fact it is so good I will cover it in a later section on this page. This class is not restricted to VB.NET code, you can use it with any other language. The interesting point about it is that it implements GetSupportedAttributes which means that the <add> element can have attributes other than the three I mentioned above. I will cover these attributes in a later section. As you'll see next, it is a pity that the other trace listeners do not support custom attributes too.

4.2 Default Trace Listener

Earlier I mentioned that trace messages are sent to the trace listeners in the Listeners collection. Both Trace and Debug have a Listeners property but they are actually the same static collection. When you start an application by default you will have an instance of DefaultTraceListener in the Listeners collection. I will have more to say about this in this section, but note that this trace listener will send trace messages to the Windows output debug stream. To view the output debug stream you have three options. The first option is to use the Visual Studio debugger, the second is to use a third party tool like dbgview from SysInternals and the final option is to write your own. There is one output debug stream for each machine, and this means that it is shared between all processes.

The actual message that is logged to the output debug stream is the process ID appended with the message. The Visual Studio debugger has to attach to a process to show its output debug stream and so since the debugger knows the process ID (and presumably so does the user running the debugger) Visual Studio displays just the message (ie it strips the process ID part of the message). The unmanaged debugger API (WaitForDebugEvent/ContinueDebugEvent) can can return output debug strings; it is relatively easy to write a process that will attach (or start) a process and show such strings.

However, it is possible to get a lower level access to the output debug string. The Platform SDK used to have the source code for a tool called dbmon, a command line tool that displayed output debug strings. To share data between processes the output debug string mechanism uses a named memory section, created using the memory mapped file API. The name of this section is DBWIN_BUFFER and access to it is controlled with two named kernel event objects: DBWIN_BUFFER_READY and DBWIN_DATA_READY. The OutputDebugString Win32 function will set the DBWIN_DATA_READY event after it has written data to the memory mapped file, so a reader of this data should block waiting for this event to signal. During the time that the data is being read, processes should not write to the buffer, so if OutputDebugString is called during this time it will first block waiting for DBWIN_BUFFER_READY to be signalled. When the process reading the data is finished with the buffer it will set DBWIN_BUFFER_READY which allows to OutputDebugString unblock and write its data.

DefaultTraceListener will use OutputDebugString to handle trace messages. This means that whenever you call Debug.WriteLine (or equivalent) the thread will block on a call to wait for the DBWIN_BUFFER_READY event to be set. In most cases this blocking will be momentarily and the blocking call does have a time out. However, it still does not get away from the fact that the signalled state of this event can be controlled by another process. Thus a badly written monitor program could adversely affect the performance of your application. This is not good, and it is one of the reasons why I say that release build applications should not be compiled with TRACE defined (because doing so will automatically give you a DefaultTraceListener object).

If you use dbgview then you simply have to run the tool and wait for messages to appear in its window. On the other hand, if you use the Visual Studio debugger you have to run the process under the debugger or attach the debugger to the process. If you have a Visual Studio project then it is simple to run the process under the debugger (Debug, Start Debugging). Alternatively you can use the File, Open, Project/Solution menu item to load the process EXE as if it is a solution (do not use File, Open, File). Once the process is loaded you can use the Debug, Start Debugging command to start the process under the debugger. Note that you can continue to change the process code and compile the process as long as you do so after the process has stopped. Finally, if the process is already running you can use Debug, Attach To Process to attach to a particular process. When a process is running under the debugger the output debug strings will appear in the Output window (if you cannot see it, open it with View, Output). The Output window is used for build messages as well as debugger messages, normally when you start the debugger you will see the debugger messages, but if this is not the case then select Debug from the Show output from dropdown list box.

I will use dbgview in the following discussion.

Create a file and add the following code:

#define DEBUG
using System;
using System.Diagnostics;

class App
{
   static void Main()
   {
      Debug.WriteLine("Main");
   }
}

Compile and run the process. You'll see something like this in dbgview:

The process had an ID of 2104. Notice that I have not had to indicate that I want to use this trace listener, I get it for 'free'. Now change the code like this:

static void Main()
{
   Debug.WriteLine("Main");
   Method();
}
static void Method()
{
   Debug.Indent();
   Debug.WriteLine("Method");
   Debug.Unindent();
}

The idea is that as you go deeper in the call stack the indent should get larger, so in this case there should be no indent for the Main method, and one indent (3 spaces by default) for the Method method. Be aware that it is your responsibility to call Indent and Unindent so typically you will make Indent the first line and Unindent the last line. Clearly if you have several exit points then you should call Unindent at each exit point. If you call code that might throw exceptions then you have no choice other than to use a finally block to make this call.

Here's the results:

So what has happened? Well, the implementation of DefaultTraceListener.WriteLine calls an overloaded version of WriteLine that looks like this:

private void WriteLine(string message, bool useLogFile)
{
   if (base.NeedIndent)
   {
      this.WriteIndent();
   }
   this.Write(message + "\r\n", useLogFile);
   base.NeedIndent = true;
}

Notice that it does not create a string and send that to Write, instead it writing the indent and the message are performed in two operations. That means two calls to OutputDebugString, which is why there appears to be a blank line in the output. This is not a blank line, it is actually three spaces. Do you see why I mentioned earlier that the formatting does not always work? I am surprised that the author of this class did not realise that this would happen and write this method so that it used a formatted string instead, but as I mentioned earlier, there are plenty of issues with the trace listeners implementation even in version 2.0 (and hence 3.0) of the framework library.

Now change the call in the Main method to be:

Debug.WriteLine("Main", "level one");

The result will be:

[2201] level one: Main
[2201]
[2201] Method

Now you have used the version of WriteLine that takes a category string. As you can see the category is at the start of the line. Now change the code like this:

static void Main()
{
   Debug.WriteLine("Main", "level one");
   Method();

   App app = new App();
   Debug.WriteLine(app);
}

Now the result will be:

[2230] level one: Main
[2230]
[2230] Method
[2230] App

The default implementation of ToString is the name of the class, so when you pass the app object to WriteLine the result is the name of the class. Add the following method:

public override string ToString()
{
   return "application entry point object";
}

Compile and run the code to confirm that the new string will be logged. Finally, add the following line to the Main method:

Debug.Print("Process id is {0}", Process.GetCurrentProcess().Id);

This will format a string in one go, so when you run the process you'll see something like this:

[2240] level one: Main
[2240]
[2240] Method
[2240] application entry point object
[2240] Process id is 2240

If you are astute you would have noticed earlier that the DefaultTraceListener does more than just trace the message to the output debug stream: it can also log messages to a file. To do this you have to set the name of the log file. You can either make sure that the trace listener is told to use this file when it is created, or you can change an existing object. Every trace listener is derived from TraceListener class and this has a Name property. The trace listener that is created by the framework for every application domain is called Default. So to change this specific object add the following code:

static void Main()
{
   DefaultTraceListener dtl = Debug.Listeners["Default"] as DefaultTraceListener;
   dtl.LogFileName = "app.log";

Now when you run the application you'll see that a file called app.log will be created and it will contain this text:

level one: Main
   Method
application entry point object
Process id is 368

This time the indent has worked. Run the application again. This time you'll find that the new data will be appended to the log file. It is worth pointing out that there is a trace listener specifically for log files: TextWriterTraceListener, which will be covered in the next section.

Finally, let's return back to this issue of a default trace listener. I am sure that you accept my argument that a release build should not be built with TRACE defined so that there is no possibility of any Trace methods being called. However, the Listeners collection is global to the application domain, so any library loaded in the application domain will also have access to the Listeners collection. This means that if you use a library written by someone else they could have code stuffed full of calls to Trace.Assert and Trace.WriteLine with the result of killing your code's performance. The way round this is to get rid of the default trace listener. Here's one way to do it (the first line in your entry point):

Debug.Listeners.Clear();

However, you may decide that you want to use your configuration file to load a specific trace listener which will occur before this call. So the following would allow you to do that (if you decide that it is a good idea):

Debug.Listeners.Remove("Default");

This line should replace the lines that set the log file name. Compile this code and run the process to confirm that no trace messages are logged in dbgview.

4.3 TextWriterTraceListener

The TextWriterTraceListener class will redirect trace messages to a TextWriter. A TextWriter can be based on a stream (StreamWriter) a string (StringWriter) or a HTTP (HttpWriter and HttpTextWriter). There are all kinds of streams (for example, memory streams and sockets) and although the TextWriterTraceListener class can be used with any of these it favours one: a file stream. If you create a TextWriterTraceListener object in code you can create it based on any TextWriter you like, but if you create it through a configuration file then you have to create it based on a file.

To test this out create a file with the following (app.cs):

#define DEBUG
using System;
using System.Diagnostics;

class App
{
   static void Main()
   {
      App app = new App();
      app.Log("default domain");
   }

   public void Log(string str)
   {
      Debug.Print("{0} {1}", str, AppDomain.CurrentDomain.FriendlyName);
   }
}

The idea is that there is an instance method that logs the specified message and the name of the application domain where the call was made.

Next create a configuration file (app.exe.config):

<configuration>
   <system.diagnostics>
      <trace autoflush="true">
         <listeners>
            <clear/>
         </listeners>
      </trace>
   </system.diagnostics>
</configuration>

This merely clears the listeners collection so that we do not have the default trace listener.

Now add the following line after the <clear/> element:

<add name="Text Listener"
     type="System.Diagnostics.TextWriterTraceListener"
     initializeData="test.log" />

Compile and run the application, you should find that a file called test.log will be created and it will contain the text default domain app.exe, where app.exe is the name of the default application domain.

Notice that the type attribute gives the name of the class, but not the assembly, however, even though a partial name works with classes in assemblies already loaded in the process it is best to use the fully qualified name, particularly if you write your own trace listener. The TextWriterTraceListener class is defined as not being thread safe, so the object is locked when a one thread logs a message. This ensures that if another thread attempts to log a message it will be blocked until the first log operation has completed.

Now let's see what happens if you have more than one application domain. Change the code to look like this:

class App : MarshalByRefObject
{
   static void Main()
   {
      AppDomain appdomain = AppDomain.CreateDomain("new domain");
      App app2 = (App)appdomain.CreateInstanceAndUnwrap("app", "App");
      app2.Log("second domain");
      App app = new App();
      app.Log("default domain");
   }

Delete all log files in the current folder (del *.log). Now compile the code and then run it. Take a look at the folder. You'll find that there are now two log files, test.log and another one with test.log appended to a GUID, for example:

C:\Instrumentation\3.4>dir /b
90dc6266-c02f-4344-a67c-4e8694fbc737test.log
app.cs
app.exe
app.exe.config
test.log

Type the contents of the two log files to the command line, what do you see? test.log will have the text: second domain new domain, whereas the GUID log file will have the text first domain app.exe. Take another look at the code, you'll see that the first call to Debug.WriteLine will be in the second domain.

When an application domain is created the <listeners> node is read from the configuration file and the trace listener objects will be created. This means that each of the application domains will have a TextWriterTraceListener object that thinks it will log to a file called test.log. In 1.1 and 1.0 of the framework this situation would cause an exception because the file will be opened by the trace listener for exclusive access and hence the second attempt to open the file will fail. In .NET 3.0/2.0 this issue has been solved using delayed initialization. The class has a internal method called EnsureWriter which creates the file if it has not already been created for the current object. This method is called every time Write or WriteLine is called. So in this case when the app2.Log method is called the file test.log will be created and henceforth trace messages from the second domain will be to this file. Now when the app.Log method is called a different trace listener object will be called. When EnsureWriter is called it attempts to open test.log, and for the second TextWriterTraceListener object this call fails because the file is already open. An exception is thrown by the StreamWriter class and this exception is caught and handled by generating a new name using a random GUID. Here is the code courtesy of Reflector (edited to make it more readable):

bool createdFile = false;
string fileName = this.FileName;
for (int count = 0; count < 2; count++)
{
   try
   {
      this.writer = new StreamWriter(fileName, true, encoding, 0x1000);
      createdFile = true;
      break;
   }
   catch (IOException)
   {
      fileName = Guid.NewGuid().ToString() + fileName;
   }
   catch (UnauthorizedAccessException)
   {
      break;
   }
   catch (Exception)
   {
      break;
   }
}
if (!createdFile)
{
   this.fileName = null;
}

As you can see, it uses a curious mechanism to get a unique name: it runs the loop twice, once with the name suggested by the config file and the second time with the name with the GUID. Notice that the code tries to open the file (through a StreamWriter objec), and errors are detected through the exception throw. In effect, this code tries to detect if the file is already open.

To confirm what is happening delete all the log files and then swap the lines that call app2.Log and app.Log, compile and run the application and take a look at the log files to confirm that now the first application domain logs to test.log, while the second application domain logs to the GUID file.

I wrote about this problem with TextWriterTraceListener soon after 1.0 was released and I hope that this change in the class was prompted by my concerns. However, I have to say that I much prefer my solution to the problem. I created a class derived from TextWriterTraceListener that read the application domain name in the constructor and changed the file name accordingly. Add the following to your file and add a using statement for System.IO:

class DomainSafeTextTrace : TextWriterTraceListener
{
   public DomainSafeTextTrace() { Initialize("Trace"); }
   public DomainSafeTextTrace(string str) { Initialize(str); }
   protected void Initialize(string str)
   {
      this.Name = "DomainSafeTextTrace";
      string strFile = String.Format(
         "{0}{1}[{2}]{3}",
         Path.GetDirectoryName(str),
         Path.GetFileNameWithoutExtension(str),
         AppDomain.CurrentDomain.FriendlyName,
         Path.GetExtension(str));
      string strBase = strFile;
      while (true)
      {
         try
         {
            this.Writer = new StreamWriter(strFile, true);
            break;
         }
         catch (IOException)
         {
            strFile = string.Format(
               "{0}-{1:d2}-{2:d2}-{3:d2}", strBase,
               DateTime.Now.Hour,
               DateTime.Now.Minute, DateTime.Now.Second);
         }
      }
   }
}

This code formats the name of the log file to contain the friendly name of the application domain and in the event that this file is already open, the code appends the time to the name of the file and uses that instead.

Change the config file so that it references DomainSafeTextTrace:

<add name="Text Listener"
   type="DomainSafeTextTrace, app"
   initializeData="test.log" />

(The name of the assembly is app, so this is a fully qualified type name.) Delete all log files, compile the code and run the app. Again you'll get two log files, but this time they will have names that have the application domain name:

C:\Instrumentation\3.4>dir /b
app.cs
app.exe
app.exe.config
test[app.exe].log
test[new domain].log

I think this is a much better solution because it is clear which file corresponds to which application domain.

4.4 EventLogTraceListener

The XP Event Log is a mechanism for permanent storage of event messages. I have strong feelings about how .NET accesses the event log, but I will leave that to a later page.

The EventLogTraceListener class has two constructors, but only the one that has a single string parameter is accessible from a configuration file. The string in this case will be the name of the source, the constructor creates an instance of the EventLog class and uses the string to initialize the Source property. At this point the event log system object has not been opened; this only occurs the first time you write to the event log, when a check is performed to see if the event source exists and if it doesn't exist the source will be created (that is a registry entry will be created for the source) and then the event log will be opened.

Note that using this constructor means that the source will be created in the Applications log, that is, the trace messages will be sent to the Applications log. In my opinion this is the worst thing that could be done. Tracing (as will be explained later) is expected to produce lots of messages, and if you log lots of messages to the Applications log you will end up swamping the other, potentially useful, messages from other applications. If you decide that you really must use the event log to log trace messages (and if you do I would urge you to reconsider) then at least make your own event log so that you do not pollute the shared Applications log with your trace messages. The way to do this is to create an instance of EventLog using the constructor that takes a string for the log, source and machine. If the log does not exist, then the first time you write an event the log, and the source, will be created. Alternatively, you can call the static CreateEventSource to create the log and source.

The EventLogTraceListener class is sealed which I regard as being rather arrogant because it suggests that no one can improve upon the supplied implementation (note that TextWriterTraceListener was not sealed). Well, I have news for the writers, because like the EventLog class, the EventLogTraceListener class is poorly written and so it certainly needs improving. The first improvement I want to make concerns Write. This method merely writes the string to the event log and WriteLine simply calls Write. You have already seen the error in this when you saw how indents are handled by DefaultTraceListener. Imagine code that looks like this:

Debug.Write("Main called at: ");
Debug.WriteLine(DateTime.Now.ToLongTimeString());

This is perfectly legitimate code, (although unnecessary because the event log records the time a message is reported). However, it will generate two event log messages. This is a waste, it bloats the event log and it makes reading the messages more difficult.

Create a file (app.cs) and add the following code:

#define DEBUG
using System;
using System.Diagnostics;

class App
{
   static void Main(string[] args)
   {
      if (args.Length > 0)
      {
         if (args.Length == 2)
         {
            EventLog.Delete(args[1]);
         }
         else
         {
            EventLog.DeleteEventSource(args[0]);
         }
         return;
      }
      Debug.Write("Main called at: ");
      Debug.WriteLine(DateTime.Now.ToLongTimeString());
   }
}

Since this code will eventually create an event log and an event source I have provided a mechanism to delete an event source, or both an event log and the event sources in it. If there are two parameters then EventLog.Delete is called on the second parameter and the first parameter is ignored because deleting a log will also remove the event sources that are logged to that specific log. If just one parameter is passed then it is assumed to be an event source and that source will be deleted. If no parameters are supplied then data is logged.

Now create a configuration file, app.exe.config, to provide the information about the trace listeners to use:

<configuration>
   <system.diagnostics>
      <trace autoflush="true">
         <listeners>
            <clear/>
            <add name="Event Log Listener"
               type="System.Diagnostics.EventLogTraceListener"
               initializeData="TestSource"/>
         </listeners>
      </trace>
   </system.diagnostics>
</configuration>

This uses the framework implementation. Compile the code and then run it. Now open the event log viewer by typing eventvwr.msc on the command line or in the Run dialog. Select the Application log and at the top you should see two events:

If you view these messages (double click on an entry to view it) you'll see that the first one (chronologically, so usually the second one in the list view) is Main called at: whereas the second message is the time. Let's create a class to fix this. The EventLogTraceListener is actually quite a simple class, so it is simple to implement our own version. As I mentioned earlier, you cannot derive from the class but replicating its code is easy. Add the following to the assembly code:

class ImprovedEventLogTraceListener : TraceListener
{
   private EventLog eventLog;
   private string buffered;

   public ImprovedEventLogTraceListener(string str)
   {
      eventLog = new EventLog();
      eventLog.Source = str;
   }
   public override void WriteLine(string message)
   {
      if (this.eventLog != null)
      {
         if (buffered != null)
         {
            this.eventLog.WriteEntry(buffered + message);
            buffered = null;
         }
         else
         {
            this.eventLog.WriteEntry(message);
         }
      }
   }
   public override void Write(string message)
   {
      if (buffered != null)
         buffered += message;
      else
         buffered = message;
   }
   protected override void Dispose(bool disposing)
   {
      if (disposing)
      {
         this.Close();
      }
   }
   public override void Close()
   {
      if (buffered != null && this.eventLog != null)
      {
         this.eventLog.WriteEntry(buffered);
      }
      if (this.eventLog != null)
      {
         this.eventLog.Close();
      }
   }
}

The constructor creates the EventLog object and initializes its source to the string passed to the constructor (and hence provided through initializeData). Since the event log object is based on an unmanaged resource the class closes the event log in the Dispose method and also provides a Close method that also does this.

Now for the code that fixes Write. The class has a string buffer called buffered and when Write is called the message is added to this buffer. The data in this buffer is sent to the event log in two situations. The first case is when WriteLine is called, in which case it is assumed that the WriteLine is called to complete the message and so the string passed to WriteLine  is appended to the buffer and the entire buffer is sent to the event log. The second case is when the listener is closed. I do not implement Flush on this class. The reason is that if AutoFlush is set then Flush will be called whenever Write or WriteLine is called and thus the buffering would be useless.

Compile this code, then change the configuration file so that your trace listener is used:

type="ImprovedEventLogTraceListener,app"

Now run the application. Refresh the view in the event log viewer (Action, Refresh) and this time you will find just one message is logged which contains the complete message.

Now delete the source by providing the name of the source on the command line

C:\Instrumentation\3.6>app TestSource

To show that the source has been deleted, open one of the message logged to this source in the event log. You'll see a message saying: The description for Event ID ( 0 ) in Source ( TestSource ) cannot be found. This indicates that there is no registry entry for the source.

The next thing to do is to allow you to pass the name of a log through a configuration file. To do this the string in initializeData has to be in this specific format: the log name, a colon, followed by the source name, or just the source name. Change the constructor to the following:

public ImprovedEventLogTraceListener(string str)
{
   string logName = "";
   string sourceName = str;
   if (str.IndexOf(':') >= 0)
   {
      logName = str.Substring(0, str.IndexOf(':'));
      sourceName = str.Substring(str.IndexOf(':') + 1);
   }
   eventLog = new EventLog(logName, ".", sourceName);
}

This extracts the log name and source name from the string and uses them to initialize an EventLog object. Compile the code and change the configuration file to provide a log:source pair:

initializeData="TestLog:TestSource"

Run the application. To see the new event log you have to close the event log viewer and then open another instance. This time you'll see a new log called TestLog. The message that you logged will not be in the Application log (check and make sure) instead, it will be logged in TestLog.

Finally, so that the new class has similar properties to EventLogTraceListener add the following:

private bool nameSet;

public EventLog EventLog
{
   get { return this.eventLog; }
   set { this.eventLog = value; }
}
public override string Name
{
   get
   {
      if (!this.nameSet && (this.eventLog != null))
      {
         this.nameSet = true;
         base.Name = this.eventLog.Source;
      }
      return base.Name;
   }
   set
   {
      this.nameSet = true;
      base.Name = value;
   }
}

Now you have an event log trace listener that works much better than the one provided with the framework. It implements Write with a buffer, and it allows you to log messages to a separate event log, preventing your application from polluting the Application event log with trivial messages.

Finally, remove the event source and event log by calling the application with two parameters:

app TestSource TestLog

4.5 .NET 3.0/2.0 Trace Listeners

The trace listeners covered so far were all introduced in .NET 1.0. .NET 2.0 (and hence 3.0) added some more: the three covered in this section and the VB trace listener covered in the next section. The three new trace listeners in System.Diagnostics are all derived from TextWriterTraceListener, and hence have the same issues as that class. The simplest of these is ConsoleTraceListener, which will send all its output to Console.Out (the default) or Console.Error. In effect creating an instance of ConsoleTraceListener is the same as calling this code:

Debug.Listeners.Add(new TextWriterTraceListener(Console.Out));

The class has two constructors, the default (parameterless) constructor and one that takes a Boolean. If this parameter is true then Console.Error is used instead of Console.Out. To test this out, create a file (app.cs) and add the following:

#define DEBUG
using System;
using System.Diagnostics;

class App
{
   static void Main()
   {
      Console.WriteLine("About to do something");
      Debug.WriteLine("Done something");
      Console.WriteLine("Going to do something that will fail");
      Debug.Fail("Something failed");
   }
}

Now create a configuration file that uses the ConsoleTraceListener listener (app.exe.config):

<configuration>
   <system.diagnostics>
      <trace autoflush="true">
         <listeners>
            <clear/>
            <add name="Console Listener"
                 type="System.Diagnostics.ConsoleTraceListener"/>
         </listeners>
      </trace>
   </system.diagnostics>
</configuration>

Compile and then run this code. You'll see the following on the command line:

About to do something
Done something
Going to do something that will fail
Fail: Something failed

This is what you would expect, but note that there is no distinction between the data that was sent to the console by the application and the tracing information. You can redirect the tracing information to the error stream using the initializeData attribute in the configuration file:

<add name="Console Listener"
     type="System.Diagnostics.ConsoleTraceListener"
     initializeData="true"/>

This will call the Boolean constructor and pass true. Run the application again. What do you see? If you see the same results as before, then you've made the correct changes. The reason is that by default the error stream (STDERR) will be sent to the command line. To change this redirect the error stream when you invoke the application:

app 2>err.txt

STDERR has a handle of 2 and this command linw will redirect everything written to that handle to the file err.txt. Run the application again. This time you will see that the tracing statements are no longer printed on the command line. Print out the contents of the file (type err.txt) and you will see the tracing statements.

Of course, if your application is GUI (or a service, or ASP.NET) then you will not have a console, so the tracing statements will not be sent anywhere. However, you can redirect the Console streams as I'll show later.

The next new trace listener, DelimitedListTraceListener, adds more functionality, but on immediate sight it seems to do very little. This class allows you to initialize it with a stream, like with TextWriterTraceListener, and it has a constructor with a string parameter that will be used for a file name and initialized through the initializeData attribute in the configuration file. In addition, you can provide a delimiter attribute to specify the character that will be used to delimit items in the output. Change the configuration file accordingly:

<add name="Delimited Listener"
     type="System.Diagnostics.DelimitedListTraceListener"
     initializeData="app.log" delimiter=","/>

Run the application. You should find that a file app.log is created and it will contain the trace messages. Note that the delimiter is not used because there is just one item on each line: the message. You can specify additional items, but to do that will require using a trace source and that subject will be covered on a later page.

The final class I'll cover is XmlWriterTraceListener, which as the name suggests will write XML to a stream. If you create an instance using the configuration file then the the initializeData attribute is used to give the name of the file:

<add name="XML Listener"
     type="System.Diagnostics.XmlWriterTraceListener"
     initializeData="app.xml"/>

Run the application. You'll see that a file, app.xml, has been created. Open this file, you'll see something like this:

<E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">
   <System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">
      <EventID>0</EventID>
      <Type>3</Type>
      <SubType Name="Information">0</SubType>
      <Level>8</Level>
      <TimeCreated SystemTime="2006-06-30T15:54:50.3622272+01:00" />
      <Source Name="Trace" />
      <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
      <Execution ProcessName="app" ProcessID="3300" ThreadID="1" />
      <Channel/>
      <Computer>MARS</Computer>
   </System>
   <ApplicationData>Done something</ApplicationData>
</E2ETraceEvent>
<E2ETraceEvent xmlns="http://schemas.microsoft.com/2004/06/E2ETraceEvent">
   <System xmlns="http://schemas.microsoft.com/2004/06/windows/eventlog/system">
      <EventID>0</EventID>
      <Type>3</Type>
      <SubType Name="Error">0</SubType>
      <Level>2</Level>
      <TimeCreated SystemTime="2006-06-30T15:54:50.7628032+01:00" />
      <Source Name="Trace" />
      <Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
      <Execution ProcessName="app" ProcessID="3300" ThreadID="1" />
      <Channel/>
      <Computer>MARS</Computer>
   </System>
   <ApplicationData>Something failed</ApplicationData>
</E2ETraceEvent>

As you can see the messages that were traces show up in the <ApplicationData> elements. The other items are addition data that are provided by trace sources and will be explained on the later page for instance trace sources.

4.6 Redirecting Console Streams

When you write to the Console object you are actually writing to the TextWriter accessed through the static Console.Out property. In this example we will replace this object. Create a file app.cs and add this code:

#define DEBUG
using System;
using System.IO;
using System.Diagnostics;
using System.Windows.Forms;
using System.Text;

class DebuggerWindow : Form
{
   ListView lvMsg;

   public DebuggerWindow()
   {
      lvMsg = new ListView();
      lvMsg.View = View.Details;
      ColumnHeader hdr = new ColumnHeader();
      hdr.Text = "Date Time";
      lvMsg.Columns.Add(hdr);
      hdr = new ColumnHeader();
      hdr.Text = "Description";
      lvMsg.Columns.Add(hdr);
      lvMsg.Dock = DockStyle.Fill;
      this.Controls.Add(lvMsg);
      this.Text = "Console.Out";
   }

   public void AddMessage(string msg)
   {
      string date = String.Format("{0} {1}",
         DateTime.Now.ToShortDateString(),
         DateTime.Now.ToShortTimeString());
      ListViewItem lvi = new ListViewItem(
         new string[] { date, msg });
      lvMsg.Items.Add(lvi);
   }
}

This code is a simple form with a ListView control that has two columns. It has a public method, AddMessage, that takes a single string. This string, and the date and time that it was accepted, are added as an item to the list view. The DebuggerWindow will be used by the implementation of TextWriter. Add the following class:

class DialogTextWriter : TextWriter, IDisposable
{
   DebuggerWindow dbg;
   StringBuilder buffer;
   int endlineIdx;
   TextWriter parent;

   public DialogTextWriter()
   {
      dbg = new DebuggerWindow();
      endlineIdx = 0;
      parent = Console.Out;
      Console.SetOut(this);
   }
   public new void Dispose()
   {
      if (dbg != null)
      {
         dbg.AddMessage(buffer.ToString());
         dbg.Hide();
         dbg.Dispose();
         dbg = null;
      }
      Console.SetOut(parent);
   }
   public void Show(IWin32Window parent)
   {
      if (dbg != null) dbg.Show(parent);
   }
   public void Hide()
   {
      if (dbg != null) dbg.Hide();
   }
   public override void Write(char ch)
   {
      if (buffer == null) buffer = new StringBuilder();
      if (ch == CoreNewLine[endlineIdx])
      {
         // Eat it
         endlineIdx++;
         if (endlineIdx == CoreNewLine.Length)
         {
            // End line, so report the message
            string line = buffer.ToString();
            if (dbg != null) dbg.AddMessage(line);
            parent.WriteLine(line);
            buffer = new StringBuilder();
            endlineIdx = 0;
         }
         return;
      }
      if (endlineIdx > 0)
      {
         // End line characters have not been sent consecutively
         endlineIdx = 0;
      }
      buffer.Append(ch);
   }
   public override Encoding Encoding
   {
      get { return Encoding.UTF8; }
   }
}

The abstract TextWriter class is actually a fairly complete implementation, there is just one member, the Encoding property, that is marked as abstract, which is why it has to be implemented. This text writer will send the data to a DebuggerWindow and since this contains an unmanaged resource I implement a Dispose method to hide the window and dispose it. When the text writer is created it creates the debugger window and then it replaces the Console.Out text writer with itself. Notice that the code stores the original object so that when this text writer object is disposed it can replace the Console.Out object with the original.

The TextWriter class has many Write and WriteLine methods, but all of them will call the Write(char) method, so that is why there is just one overrided method in this class. The implementation buffers the characters passed to it and will only 'flush' the buffer if the 'endline' sequence has been passed (defined by the CoreNewLine property).

Now create a form that uses these classes. Add the following class to the file:

class App : Form
{
   App()
   {
      DialogTextWriter tw = new DialogTextWriter();
      tw.Show(this);
      Console.WriteLine("this is from Console.WriteLine{0}and another message", Environment.NewLine);
      Debug.WriteLine("this comes from Debug");
      Click += new EventHandler(click);
   }

   void click(object o, EventArgs args)
   {
      Debug.WriteLine("click");
   }

   static void Main()
   {
      Application.Run(new App());
   }
}

This class creates a form with a click event. The handler for the event will trace a message to the Debug class. In addition, the constructor, that creates the new text writer object, calls Console.WriteLine. (It 'writes' a string which contains a newline.)

Compile this code as a windows application:

csc /t:winexe app.cs

now run it from the command line. You'll see that there are two windows. However, the debugger window will only show the messages from the call to Console.WriteLine. To redirect the messages from Debug.WriteLine you need to create a configuration file to add a ConsoleTraceListener:

<configuration>
   <system.diagnostics>
      <trace>
         <listeners>
            <clear/>
            <add name="console"
                 type="System.Diagnostics.ConsoleTraceListener"/>
         </listeners>
      </trace>
   </system.diagnostics>
</configuration>

Now run the application again. This time, whenever you click on the main window a message will appear in the debugger window.

4.7 VB.NET Logging

In the past  have been terribly rude about Visual Basic, and I think I have been justified. The Visual Basic team have added many nasty things into .NET (edit and continue is one feature that I regard as being a pointless waste of time), and I even think that creating a new language, VB.NET, was unnecessary when a perfectly adequate language (C#) existed. So imagine my reaction when I saw the classes in the Microsoft.VisualBasic.Logging namespace. That's right, I sighed because I expected some other code that I would have to try and fix. But I was wrong! I have to admit that I am unlikely to use these classes (as I will explain later) but it is clear that whoever wrote them did actually think through the problems and created workable classes. If only I could say that about the classes in System.Diagnostics.

The Log class is used to log 'events' through the instancetrace source declared in the object; (as I keep saying on this page) instance trace sources will be covered later, but it is important to point out that the methods do not have the [Conditional] attribute, this is important as you'll see later. On first sight, the FileLogTraceListener class appears to be a replacement for TextWriterTraceListener, however, as you'll see, this is not the intention for this class. The class uses custom attributes so this means that the user has far wider scope of the options to use in the configuration file. These are the attributes that you can use in the <add> node: baseFilename, location, customLocation, append, autoFlush, delimiter, encoding, includeHostName, logFileCreationSchedule, maxFileSize, diskSpaceExhaustedBehavior, reserveDiskSpace. These allow you to determine things like: the location where log files will be stored, and the base part of the name of those files; determine the maximum size of a file and whether an exception is thrown when the log file exceeds that size. This listener generates log names from the BaseFileName property and if the LogFileCreationSchedule indicates a daily or weekly log then the date is incorporated into the name. If this still creates a file that already exists then an integer is added to the end of the file name.

The class maintains a cache of the files currently in use, and if the same file is used by two instances of FileLogTraceListener in the same process then the file will be shared; if there are multiple processes using FileLogTraceListener objects then different files will be used.

As the various properties suggest, this class is intended to be used for long term logging, that is, it is not intended to be used for tracing debug information but instead it is intended to be used to maintain a log of what your application is doing.

Take heed VB.NET programmers! Do not use this class for tracing data, only use it for logging data.

You are expected to use an instance of the Log class to log messages, but as I mentioned earlier, since the methods do not have the [Conditional] attribute then these methods are intended to be called by release mode code. There are valid reasons for this. For example, IIS keeps a log of all the accesses made so that you can analyse which pages are read and how many users there are for your web site.

The LogFileCreationSchedule property has a value of Daily, Weekly or None, and before an entry is logged a check is performed to see if the day has changed, and from the schedule, it determines if a new log file should be created.

It is important to realise that FileLogTraceListener is still a trace listener, and if you have any Debug or Trace calls they will be logged to the log file. Since the intention of the FileLogTraceListener class is to allow you to log application data and not debugging data it highlights yet again that you should not define TRACE for release builds. (If you are still not convinced, imagine what would happen if IIS debugging information were sent to the IIS log files. One immediate downside would be that tools designed to analyse IIS log files would not work.)

I hope that you enjoy this tutorial and value the knowledge that you will gain from it. I am always pleased to hear from people who use this tutorial (contact me). If you find this tutorial useful then please also email your comments to mvpga@microsoft.com.

Errata

If you see an error on this page, please contact me and I will fix the problem.

Page Five

This page is (c) 2007 Richard Grimes, all rights reserved