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:
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:
| Class | Logs 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:
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:
{
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:
{
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:
The result will be:
[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:
{
Debug.WriteLine("Main", "level one");
Method();
App app = new App();
Debug.WriteLine(app);
}
Now the result will be:
[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:
{
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:
This will format a string in one go, so when you run the process you'll see something like this:
[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:
{
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:
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):
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):
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):
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):
<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:
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.
{
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:
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):
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:
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:
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.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:
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:
<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:
{
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:
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
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:
{
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:
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:
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:
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:
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:
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):
<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:
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:
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:
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:
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:
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:
<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:
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:
{
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:
{
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:
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:
<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.