6. .NET 3.0/2.0 Trace Source

Trace Listeners gather information passed to them and store the data. In .NET 1.0 and 1.1 the mechanism to generate trace information was to use static members on the Trace or, preferably, the Debug class. However, this information was simply a single line message (possibly concatenated with the detailed message), or a multi line message for asserts. This mechanism is still available in .NET 3.0/2.0. In addition, .NET 3.0/2.0 also provides a class called TraceSource that gives far more information about the process at the time that the message was generated. This class has more scope for customization and for this reason the methods to generate messages are instance methods, which means that you can have several trace sources in your application, each with a different configuration.

To generate trace messages with Trace or Debug you call static members. These classes delegate their work to a single class called TraceInternal. This means that the trace configuration is global to the application domain. So once you have set the indentation size, that size will be used by all tracing calls, regardless of the class, thread or assembly where the call was made.

In .NET 3.0/2.0 trace sources were introduced to address two issues. The first issue is the amount of tracing data that is generated. TraceInternal will simply pass the message (and if provided, the detailed message) to the trace listeners. TraceSource will add extra information to the message, information like the time, the process ID and thread ID. The other issue is to remove the global aspect of tracing in 1.0 and 1.1 and make it more granular. To do this, the tracing methods are now instance methods, so they must be called on trace source objects, and each trace source object has its own configuration, including its own collection of trace listeners.

The TraceSource class has three methods (each one overloaded) to trace messages: TraceData, TraceEvent and TraceInformation, which will be covered in detail later. Note that all of these methods are conditional on TRACE. That's right, to use the TraceSource class you must define the TRACE symbol. I would have preferred the methods to be conditional on DEBUG but I guess TRACE seemed more logical given the name of the class.

Note also that the constructors do not have the [Conditional] attribute, and neither do the properties, because only methods can have this attribute. Furthermore, the Flush method (which only makes sense if you have generated one or more messages) also does not have the [Conditional] attribute. This means that you are able to create an instance of the TraceSource class in an application that does not have the TRACE symbol defined and you can call Flush on it, but you cannot call any of the object's useful methods. If you want to prevent this object from being created in this situation you have to use conditional compilation. This can make your code rather messy.

The most generic method on TraceSource is TraceEvent, and the most generic overload is this one:

The last two parameters are used to create the trace message: format is a format string with WriteLine-like placeholders that are replaced with formatted values from the args parameter. This is marked as params and so C# treats the object array like varargs, (which it isn't, of course). The id parameter is whatever you choose it to be, there is no compulsion that a particular ID is associated with a particular format message. When I first saw this method I thought that it had been created this way so that the EventLogTraceListener would be able to log messages to the event log in a proper way. However, I should have realised that the people who wrote the EventLog class do not really understand how this service works. I say this because the event ID identifies the format string, so that would make the format parameter redundant. In fact, the implementation of EventLogTraceListener does not use the ID in any way that can be considered correct and it merely generates a single string like this:

EventLogTraceListener then passes this and the ID to the event log as usual with the WriteEvent method. A nasty and lazy implementation.

The first parameter of TraceEvent is an enumeration that gives the severity of the message. This encompasses the severities that are possible with the event log, and it provides seven more:

Note that this does not have [Flags] and so the values cannot be combined. The first four values refer to the state of the application, indicating a crash, an exception, a warning or just some information message. The Verbose value indicates that the message is a verbose information message. The next four values indicate that some logical operation has started, stopped, has been suspended or resumed. The final value indicates a change in the correlation, which will be explained later.

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

Note that the TRACE symbol must be defined. The code creates a trace source called Default Source and it will be used to trace all message types. The second parameter sets the Switch property which can be changed during execution. The Switch value determines whether the trace source will pass the message to the trace listeners. This is, if you like the first level of filtering that is possible with trace sources.

The values of SourceLevels are shown here:

Notice that it is marked with [Flags] which suggests that the values should be treated as bit fields, that is, they can be combined. However, this is nonsense because Error contains the bit of Critical (is an error critical?); Warning contains the bits of Error and Critical; Information contains the bits of Warning, Error and Critical; and Verbose contains the bits of them all! So ignore [Flags] and treat the values as if they are appended with AndMoreSevere, that is treat SourceLevel.Warning as being WarningAndMoreSevere (that is, Warning, Error and Critical). When you log an event the class will perform a bit comparison of the Switch value with the type of the event being reported and if the appropriate bits are set then the event is logged. Note that to be able to report Start, Stop, Suspend, Resume or Transfer messages the trace source must be set to ActivityTracing (or All).

The next line of the sample code adds a trace listener to the Listeners collection of the source. Be aware that you will have an instance of DefaultTraceListener by default. Note the warnings I gave earlier in this workshop that DefaultTraceListener has some nasty side effects that in most cases you do not want. This is why I added the line to clear the Listeners collection so that you only get a DefaultTraceListener instance if you explicitly add one.

Finally, the code logs an information message to the source. Compile this code and run it, the results should be:

Now change the code to use a DelimitedListTraceListener:

Since the delimited list will be sent to a file you have to ensure that the trace listener is flushed, hence the last line. Compile and run this code. You should get something like this (type app.log):

The default delimiter is a semicolon, but you can change this by using a constructor that takes a string as the second parameter or by changing the Delimiter property. Notice all of those semicolons at the end: clearly there are values that the trace listener is printing out that have null values.

The extra values shown by the delimiter list in the last section are generated by the trace listener rather than the trace source. These values are generated by the trace listener if it is instructed to do so through the listener's TraceOutputOptions property which is a combination of values from TraceOptions enumeration:

This enumeration has the [Flags] attribute, so you can combine them. The values you are most likely to use are DateTime and ThreadId, so that you have a record of when the event was generated and which thread generated the event (assuming you have a multi threaded app). If you have multiple processes in your application then you can use ProcessId, however, note that to make this useful the different processes will have to log to a shared resource, which effectively means the event log or the output debug stream. (Files are not shareable between processes.) The Timestamp value is a long value that represents the current tick count of the system clock. This is useful to order events.

The two stack values are interesting. As the name suggests, Callstack provides the current call stack, returned by calling Environment.StackTrace. In fact the implementation is rather dumb. If you log from the Main method you'll get something like this:

All I am interested in is where the TraceEvent method was called, I am not interested in the entire stack! If I call TraceEvent deep in my call stack then it would be easy to lose where the TraceEvent method was called. Furthermore, the string contains newline characters and hence this messes the formatting of the messages if ythey are logged to the event log, or to a file. For these reasons I regard this option as being less than useful.

The other stack option is LogicalOperationStack. This logical stack is managed by the correlation manager, which is accessed through the Trace class.

To test out these values, change the code from the last section to these lines:

This will print the trace messages to the console. The trace options are: DateTime, Timestamp, ProcessId and ThreadId. Compile and run this. You'll get a result like this:

Notice that the extra trace options are given after the main trace message; this is because they form the footer of the traced event.

The logical operation stack is created by starting a new logical operation. To do this you access the correlation manager through the Trace class. Make following changes:

Here, you just want to trace the logical operations, and you tell the correlation manager to start operation one before tracing the message, and stop the logical operation after the trace. Compile the code and run it. The result will be:

Logical operations are nested. To see how this works, change the code so that the source is a static member:

Next, add two static methods:

Finally, change Main so that it calls MethodOne:

Compile and run this code. The result should be something like this:

Notice how the logical stack is in reverse order, that is, the string from last call to StartLogicalOperation appears first. If you call StartLogicalOperation without a string then a GUID will be generated and the value of that GUID will be printed instead. The correlation manager maintains a thread based logical operation stack, so each thread in the process that logs an event with this trace source will show its own logical call stack. Note that the parameter of StartLogicalOperation is an object, so you can provide any type of object, but be aware that the footer calls ToString on this object, so this method must return something meaningful.

There are three methods on TraceSource to trace data: TraceEvent, TraceData and TraceInformation. TraceEvent has already been covered. TraceData has two overloads and both take a TraceEventType and an ID. The difference is that one overload takes an object and the other takes an array of object (marked as params). Again, this looks as if it could be useful for passing data to the event log. However, this is not the case. TraceData calls a similarly named method on each trace listener and the implementation of the trace listeners in the framework will call ToString on the object. If the method is called with an array of objects then a comma separated list will be created by calling ToString on each object. The EventLogTraceListener class behaves ;like this too, so yet again, the writers of this class have failed to create a method that works correctly.

TraceInformation takes either a string, or a format string and a params array of objects that will be placed in the format string. This method merely calls TraceEvent passing the string (or the formatted string) and an ID of 0 and a message type of TraceEventType.Information.

The Trace has three static methods not covered so far: TraceInformation, TraceWarning and TraceError. These methods will generate information, warning and error messages by calling TraceEvent on all the trace listeners in the application domain's Listeners collection. Since a trace source is not used it means that there is no Switch settings and hence there is no check on the event's type to determine if it should be traced.

So far I have showed how you can instantiate trace sources. They become far more useful when they are instantiated through entries in a configuration file.

To test out basic configuration create the following application (app.cs) and compile it:

Compile and run this code. You should find that the message will appear on the command line.

The SourceLevels.All value indicates that the source will log events of all severities. Remove the SourceLevels parameter from the constructor of the static member, so that the TraceSource  constructor with just one string parameter is called: this is the name of the source, TestSource.

Compile and run this application. This time the message will not appear on the command line because the Switch property of the TraceSource is not being set. Create a configuration file (app.exe.config):

Notice that this entry has the same name as the trace object. The value is the string value of a SourceLevels member. Run the application. This time you'll see the message. To show that it is this switch value that is controlling whether the event is logged, change the value to Off and run the application again. This time the message won't be logged. Change the value back to All.

Now remove the code that adds the ConsoleTraceListener to the trace source so that Main now looks like this:

Compile the code.

You now need to change the configuration file so that the trace listener is specified. To do this, add the following to the <system.diagnostics> element:

The <source> entry refers to our TraceSource object using its name. Run the application again to confirm that it still logs a message to the command line.

As you can see, each source has its own <listeners> collection. This might work well with how you've designed you application. On the other hand, you may decide that you would prefer several sources to share the same trace listener. To do this you need to add a <sharedListeners> collection under the <system.diagnostics> element:

The name is important, because it is referred to in the <listeners> collection of the source. Remove the type attribute, so that the source looks like this:

Run the application again and confirm that the message appears on the command line, showing that the source uses the shared listener.

In this application the trace source Switch property is initialized with the value of the <switch> element that has the same name as the <source> entry and the Name property of the TraceSource object in the application. It is worth pointing out that the <source> element has an attribute called switchName, so that you can supply the source level through a switch other than one with the same name as the trace source, like this:

You can now change the switch:

Keep the sample code, it will be used in the next section.

If you read the documentation for the <source> element you'll see that it mentions an attribute called extraAttribute. In fact this is not necessarily the name of the attribute, it is just a placeholder. A class derived from TraceSource can support any number of attributes. To do this you need to derive from TraceSource and provide the names of the additional attributes through the protected GetSupportedAttributes method.

This sample uses the files from the last section as a starting point (app.cs and app.exe.config). Add a new class to the process:

This class indicates that it supports an attribute called ignore (with two alternate spellings). This is used in the TraceEvent method that hides the inherited version. TraceEvent treats this attribute as a number and will only trace a message if the ID is less than or equal to the ignore attribute. Change the code so that the new trace source is used, and change the ID to 10:

Compile and run this code. Since the configuration file does not have the ignore attribute the message will be generated. Now change the configuration file to ignore messages over 5:

This time you'll find that the message is not generated. change the ignore value to 20 and run the application again. The message will be generated.

You can use attributes for whatever use you choose, however, note that there is a better mechanism available to filter messages.

Trace listeners can use filters to determine if a message should be traced. A filter derives from the abstract TraceFilter class and provides an implementation of the ShouldTrace method:

The following table is a summary of these parameters:

There are so many parameters because there are so many different ways to log a message. TraceSource has TraceEvent and TraceData, and there are various overloads of these methods. ShouldTrace is called when any of these overloads is called and the parameters that are absent are passed as null values.

A simple implementation of TraceFilter is provided by the framework. This is called SourceFilter. The class is initialized with the name of a source (which is also accessible through its Source property) and ShouldTrace will return true only if the message is generated by the specified source. This means that if you have multiple trace sources you can indicate that a particular listener will only handle the messages from the specified source. The <filter> child element is available for listeners in the <listeners> collection for Trace and Debug (ie the global <listeners> collection under <trace>), the <sharedListeners> collection and the <listeners> collection for each source (although in this last case SourceFilter seems unnecessary).

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

This creates three trace sources which are used to trace messages in the application. Now create a configuration file (app.exe.config):

Compile the code and then run it. You'll see that you get only one message, the message is generated by SourceOne in Main. The reason is that the filter for the shared listener only allows messages from SourceOne. Change this entry in the configuration file to SourceTwo and repeat the test. Finally change the entry to SourceThree and repeat the test. Each time you'll see that only the message from the specified source will be generated.

This raises the question: how do you trace from two out of the three sources? Try adding a second <filter> to the shared listener, one each for SourceTwo and SourceThree. Run the code. You should find that a ConfigurationErrorsException will be thrown. The reason is that you can only have one filter for each listener. You have three options. First, for this particular example you can use the <switches> collection to have the same effect, in this case remove the <filter> entry and edit the <switches> to look like this:

Run the application to confirm that you get the results you expected.

However, this is cheating somewhat because it does not use filters. The problem is that a trace listener can only have one filter, and because of the way that SourceFilter works if you have a shared listener then the filter only allows message from one source. This is your second option. To filter out just one of the three you need to use a trace listener for each source. Return the switches back to how they were before and change the sources to this:

This appears obvious, the filter for SourceOne says that only messages for SourceOne will generated, the same for SourceTwo and SourceThree. Run the application and confirm that all three messages are generated. Now change the filter for SourceOne so that only messages generated for source doesNotExist will be generated. Note that it does not matter that they all have the same name.

I would prefer to use a shared listener and use a filter that takes more than one source. Your third option, and the best of the three, is to write your own filter. Add the following code to the process:

This takes a comma separated list of sources. ShouldTrace checks this list to see if it contains the source. Return the configuration file back to the text where the sources all use the shared listener Console. Now indicate that you want the shared listener to use the custom filter:

Compile the application and then run it. This time you'll find that messages from SourceTwo and SourceThree will be generated.

I regard tracing in .NET as work in progress: what we have got is fine, but it could be so much better. The frustrating thing is that Microsoft had a wonderful tracing system in Visual Studio 7.0 and yet the .NET team seemed to have 're-invented the wheel' and come up with an inferior copy. Of course, I am referring to ATL tracing. .NET tracing has some features that ATL doesn't - trace listeners and customizable filters are the two best features of .NET tracing - but the .NET diagnostics designer could have made tracing so much better if they took a look at how ATL does the same thing.

With ATL tracing in mind, here's a wish list for .NET tracing:

• Tracing on an assembly basis. The footer does not contain assembly information, and thus TraceFilter.ShouldTrace is not passed assembly information. To trace on a per-assembly basis you need to create a distinct trace object in every assembly and name it appropriately.
• Stack dump sucks. What would be far more useful is the name of the method and the source code line.
• Dynamic configuration. Yes, you can call Trace.Refresh, but why should you have to? Why can't the tracing system monitor the configuration file on your behalf and update the tracing configuration accordingly?

It would be nice if features like these appeared in the next version of the framework.

Errata

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

Page Seven