Having hopefully persuaded you that instrumentation and tracing is critically important when building any nontrivial application, I'll now show you how to add the most common type of tracing to your VB .NET software. You need to deal with five basic elements:
Add tracing code to your application with the Trace class.
Activate or deactivate tracing code at compile time with the TRACE flag.
Specify the destination of tracing information with the TraceListener class.
Specify the level of tracing at runtime with the TraceSwitch class.
Control and override tracing behavior at runtime with the application's configuration file.
An important point to make here is that everything I'm about to discuss deals with tracing in non-ASP .NET applications. ASP .NET tracing is done differently, and I cover it in Chapter 9, which deals with debugging ASP .NET applications.
The System.Diagnostics.Trace class is the cornerstone of instrumentation and allows you to write tracing code that sends diagnostic information to all of the current trace listeners. It has several methods for this purpose. I describe these methods in the sections that follow.
The Write method is used to produce diagnostic information without a linefeed , so that further information can then be appended to the same line. The Write-Line method is used to produce diagnostic information with a linefeed. Both of these methods are overloaded so that you can supply optional parameters. See Listing 6-1 for some examples of using this method.
'This overload takes just a string 'and will produce the trace message Some diagnostic information Trace.WriteLine("Some diagnostic information") 'This overload takes two strings, a diagnostic message and a user-defined category 'and will produce the trace message Warning: A was supposed to equal B Trace.WriteLine("A was supposed to equal B", "Warning") 'This overload takes an object and passes its.ToString value 'and will produce a trace message with the value of MyObject.ToString Trace.WriteLine(MyObject) 'This overload takes an object and a user-defined category 'and will produce the trace message Information: MyObject.ToString Trace.WriteLine(MyObject, "Information")
The interesting idea here is to find a good use for the user-defined category. One good use is shown in the preceding examples: a message level. In this scheme, you specify different levels of importance so that people looking at the tracing output can easily categorize the information into routine messages, warnings, and errors, or indeed whatever other scheme you devise . Another possibility is to specify the class name as the category, so that you can easily tell which class produced each trace message.
These two Trace class methods are almost identical to their WriteLine and Write siblings, but each also takes a boolean expression that has to evaluate to true for the trace information to be emitted . You would write something like the code shown in Listing 6-2.
Trace.WriteLineIf(IsTracingActive, GetStack() & GetDatetime() _ & "Some diagnostic info")
The only caveat with these conditional methods is performance. Even if the boolean expression evaluates to false , the whole statement will be processed ” there is no short-circuit . From the point of view of performance, it is better to write the code shown in Listing 6-3.
If IsTracingActive = True Then Trace.WriteLine(GetStack() & GetDatetime() & "Some diagnostic info") End If
These two Trace class methods implement assertions , which are safety checks within your code designed to catch conditions that theoretically shouldn't happen. Assertions are very useful because they can detect many bugs automatically, especially those bugs that result from invalid assumptions. The use of assertions is only bounded by your own imagination , but typically an assertion might be used to
Detect an illegal condition that should never occur (e.g., checking that a configuration file setting has a legal value).
Check that a component is operating properly (e.g., that a class has its internal flags in a mutually consistent state).
Check that procedure parameters supplied by your own code (as opposed to the code of another developer) are really valid.
Document an assumption that you make during coding (e.g., that another developer's component always gives an answer within a certain range).
The Assert method therefore tests an expression that you define, which should normally evaluate to true . If instead the condition evaluates to false , the assertion has failed and the Assert method automatically displays one or more messages that should contain your explanation of how and why the condition failed. See Listing 6-4 for some examples of using Trace.Assert .
Dim VbClassic As Int16, VbNet As Int16 'Does TRUE have the same value when using 'VB.Classic functions and VB .NET functions? VbClassic = CInt(True) VbNet = Convert.ToInt16(True) 'This overload just shows the call stack leading to the assertion failure Trace.Assert(VbClassic = VbNet) 'This overload adds an brief explanation of the assertion failure Trace.Assert (VbClassic = VbNet, "Assertion failed: _ VbClassic(True) <> VbNet(True)") 'This overload adds a more detailed explanation of the assertion failure Trace.Assert (VbClassic = VbNet, "Assertion failed: _ VbClassic(True) <> VbNet(True)", _ "CInt(True)=" & VbClassic.ToString & _ " : Convert.ToInt16(True)=" & VbNet.ToString)
The Fail method is simply an assertion that always fails, and it's typically used to signal that the software doesn't understand what it's trying to process. For example, a Select statement that runs out of options should use Trace.Fail to show that the Else clause has been reached. The Fail method is also overloaded, so you can supply just a single message or, as shown in the code in Listing 6-5, a summary message together with a more detailed message.
Select Case TestNum Case 1 'Valid value - something happens here Case 2 'Valid value - something happens here Case 3 'Valid value - something happens here Case Else Trace.Fail("TestNum=" & TestNum.ToString, _ "TestNumber must be between 1 and 3") End Select
One major advantage of using assertions is that the complete call stack is added automatically to the generated message. This even includes the line number of the assertion if your application is running as a debug build. Listing 6-6 shows the detailed assertion message produced by the code shown in Listing 6-4 executing as a result of a command button click.
---- DEBUG ASSERTION FAILED ---- ---- Assert Short Message ---- Assertion failed: VbClassic(True) <> VbNet(True) ---- Assert Long Message ---- CInt(True) = -1 : Convert.ToInt16(True) = 1 at TraceDebug.btnTrueIsFalse_Click(Object sender, EventArgs e) C:\Visual Studio Projects\TraceAndDebug\TraceDebug.vb(117) at Control.OnClick(EventArgs e) at Button.OnClick(EventArgs e) at Button.OnMouseUp(MouseEventArgs mevent) at Control.WmMouseUp(Message& m, MouseButtons button, Int32 clicks) at Control.WndProc(Message& m) at ButtonBase.WndProc(Message& m) at Button.WndProc(Message& m) at ControlNativeWindow.OnMessage(Message& m) at ControlNativeWindow.WndProc(Message& m) at NativeWindow.Callback(IntPtr hWnd, Int32 msg, IntPtr wparam, IntPtr lparam) at UnsafeNativeMethods.DispatchMessageW(MSG& msg) at ComponentManager.System.Windows.Forms.UnsafeNativeMethods+ IMsoComponentManager.FPushMessageLoop(Int32 dwComponentID, Int32 reason, Int32 pvLoopData) at ThreadContext.RunMessageLoop(Int32 reason, ApplicationContext context) at Application.Run(Form mainForm) at TraceDebug.Main() C:\Visual Studio Projects\TraceAndDebug\TraceDebug.vb(19)
An assertion really has two uses. During development and unit testing, an assertion failure is shown directly to the developer so that the problem can be investigated and fixed. Therefore, the default output of an assertion failure is to display the call stack and any programmer-defined messages to the developer using a message box. The developer can then choose to stop program execution immediately by clicking Abort, drop into the debugger at the point of assertion failure by clicking Retry, or ignore the failure and continue program execution by clicking Ignore.
During application integration testing and when in production, there is no point in displaying assertion failures to the end user ”these messages would just be confusing. Instead, the application can be told to redirect assertion failures to a log file. I discuss this later when I cover investigating the use of application configuration files.
An important point to remember is that assertions should not take the place of defensive programming. Assertions are intended to detect " impossible " conditions, and they can therefore be sprinkled liberally through your code in an effort to find as many problems and mistaken assumptions as possible. However, adding defensive code to cater to each and every possible assertion failure is counterproductive. Assertions should never normally fail, and adding large amounts of defensive code just makes your application more complex and introduces a strong probability of extra bugs. You should have defensive code for critical areas of your application, but try to use each assertion as a warning beacon , not as a support fixture for some defensive programming. If you are actually seeing regular assertion failures, the solution is to eliminate them by fixing the code rather than trying to defend the code.
Try to document your assertions thoroughly, as it can be very exasperating to hit an assertion failure in somebody else's code and have no idea what that assertion is trying to do. A comment explaining why the assertion check exists can help to stop rogue developers from simply ripping out your carefully constructed code.
Once you've added tracing code to your application with the Trace class, you need a way of activating and deactivating it. At compile time, this can be controlled with a conditional compilation flag called TRACE . When this flag is set to true , any Trace class method is compiled as normal; when it is set to false , any Trace class method is removed from your application. You can set this flag in one of three ways:
From the command line : Use /d:TRACE=True or /d:TRACE=False when compiling your application from the command line.
In Visual Studio : In the Project properties ’ Configuration properties ’ Build window, select or deselect the "Define TRACE constant" check box when compiling your application from VS .NET.
In code : Within your code, define the TRACE constant using the syntax #Const TRACE = True or #Const TRACE = False .
By default, the TRACE flag is set to true in all debug and release builds. Somebody made an assumption that you will normally want tracing code to be permanently enabled. This is a sensible assumption because control of the resulting diagnostic information can be done using trace switches, an option that has its own dedicated section later in this chapter (see "Step 4: Trace Control at Compilation Time").
You can also remove any diagnostic checks that you don't require when tracing is deactivated ”this can be useful for improving performance. To do this, you should use the #If #End If directive with the TRACE constant, as shown in Listing 6-7. If tracing is not active, none of the diagnostic code will be compiled into your program.
#If TRACE Then 'Some expensive diagnostic code goes here #End If
Once you've instrumented your code so that it's producing tracing information, the next step is to direct that information to the required destinations. You do this with one or more trace listeners.
The System.Diagnostics.TraceListener class is the abstract base class that you need to implement in order to create your own custom trace listeners. The job of atrace listener is to write the information emitted by the Trace class (using Write , WriteLine , and so on) to a specific destination, such as the console, a log file, or a database.
The .NET Framework provides some predefined listeners that handle the most common destinations for diagnostic information. The first is the Default-TraceListener , which writes to the OutputDebugString Win32 API, whereupon the VS .NET debugger redirects the information to the Output window. Other predefined listeners include the TextWriterTraceListener , which writes to a log file or other output stream such as the console, and the EventLogTraceListener , which writes to any of the Windows event logs. Adding an instance of one of these listeners to the Trace.Listeners collection directs tracing information to the specified destination. The following sections look at using these predefined event listeners and also cover how to define and use a custom event listener.
When you start an application with tracing, the DefaultTraceListener is automatically instantiated and added to the Trace.Listeners collection. As a result, by default all information produced by the Trace class is written to the attached debugger, which in the case of VS .NET shows the information in the Output window. Normally, you don't need to write any code to support this functionality, but Listing 6-8 shows you how to remove the default trace listener, perhaps for performance reasons.
Option Strict On Class Test Public Shared Sub Main() 'Remove the default trace listener from the listeners collection 'This method takes either a string containing the listener name 'or the listener object Trace.Listeners.Remove("DefaultTraceListener") End Sub End Class
One of the most common requirements is to log diagnostic information in a text file. The System.Diagnostics.TextWriterTraceListener class has been created specifically for this purpose. To be more precise, this class can direct tracing information to any type of Stream or Writer , which gives you considerable flexibility in arranging your output. You may, for instance, want a trace listener that writes trace information to the system console. Listing 6-9 shows how you could accomplish this.
Option Strict On Class Test Public Shared Sub Main() 'Create a trace listener that writes trace information to the console Dim objTraceToConsole As New TextWriterTraceListener(System.Console.Out) 'Add the new trace listener to the collection of listeners Trace.Listeners.Add(objTraceToConsole) 'Write trace information to all listeners, including the console Trace.WriteLine("This trace information is for all listeners") 'Write trace information to just the console listener objTraceToConsole.WriteLine _ ("This trace information is just for the console listener") 'Pause application to see console output Console.ReadLine() 'Finish and clean up our console listener objTraceToConsole.Flush() objTraceToConsole.Close() objTraceToConsole.Dispose() End Sub End Class
Notice that you can send trace information to just one specific trace listener if you wish. Although this might be useful when you want to send each category (information, error, and warning) of trace information to a different listener, it subverts the flexibility of tracing where you can add trace listeners at runtime using a configuration file and expect to see the tracing output. I go into more detail about this in the section titled "Step 5: Trace Control at Runtime."
Listing 6-9 also shows the code that you need to run when you're finished with a particular trace listener. The Flush method ensures that all the information is actually written to the console, and the Close and Dispose methods make sure that all of the resources associated with the trace listener are released in a timely manner.
Of course, you might not want to send diagnostics to the console in this manner because the information won't be recorded permanently, but it could be useful when you want an end user to view and report a specific problem.
You might also want to send the diagnostic information to a text file, especially where the tracing database is not available. Listing 6-10 shows an example of doing this.
Option Strict On Class Test Public Shared Sub Main() 'Create a trace listener that writes trace information to a text file Dim objTextFile As Stream = "TraceListener.txt" Dim objTraceToText As New TextWriterTraceListener(objTextFile) 'Add the new trace listener to the collection of listeners Trace.Listeners.Add(objTraceToText) 'Write trace information to all listeners, including the text file Trace.WriteLine("This trace information is for all listeners") 'Finish and clean up our console listener objTraceToText.Flush() objTraceToText.Close() objTraceToText.Dispose() End Sub End Class
Notice the necessity in both listings to flush and close the trace listener after you've finished with it. Although the CLR promises to perform garbage collection on an object at some point after it goes out of scope, this cleanup can be delayed for a long time. Any resources used by the object won't be released until the garbage collection has taken place, which would be bad news if some other part of the code wanted to make use of the same resources before the cleanup occurred.
The System.Diagnostics.EventLogTraceListener class allows you to direct tracing information to any of the Windows event logs. This can be very useful, especially for middle- tier application servers where administrators often expressly monitor these logs. It can also be useful for remote diagnostics because you can easily view another machine's Windows event log using your machine's event viewer if you have the right permissions.
Listing 6-11 shows you how to create a trace listener that writes tracing information to the Application event log, specifying the program and trace listener names as the event source. You can also write to a custom event log for your application by specifying the name of your application's custom log in the EventLog.Log property.
Option Strict On Class Test Public Shared Sub Main() 'Create an event log trace listener, give it a name, and configure it Dim objTraceToAppLog As New EventLogTraceListener("LogTraceListener") With objTraceToAppLog 'Write to the Application event log .EventLog.Log = "Application" 'Specify source of tracing information .EventLog.Source = "AppName." &.Name End With 'Add the new trace listener to the collection of listeners Trace.Listeners.Add(objTraceToAppLog) 'Write trace information to all listeners, 'including the Application event log Trace.WriteLine("This trace information is for all listeners") 'Finish and clean up our console listener With objTraceToAppLog .Flush() .Close() .Dispose() End With End Sub End Class
It's important to remember that the Windows event log has limited storage available. If you wish to write to the event log, it's better to do this away from the main code path ”in other words, only when an error has occurred. If you insist on writing routine information, anybody monitoring the event log is likely to be drowned in diagnostic information, and the event log may also run out of space rather quickly.
You can also create a custom trace listener when you want to send diagnostics to a nonstandard destination or augment the tracing information in some manner. Listing 6-12 shows a custom trace listener derived from the TextWriterTraceListener class. This custom trace listener writes timing information to an XML trace file to record specific performance information produced by your application.
Option Strict On Imports System.Diagnostics Imports System.Threading Imports System.Text Imports System.IO Imports System Public Class TimerTraceListener : Inherits TextWriterTraceListener Private msbBuffer As New StringBuilder() 'All of our constructors are here Public Sub New(ByVal Stream As Stream) MyBase.New(Stream) EmitHeader() End Sub Public Sub New(ByVal Stream As Stream, ByVal Name As String) MyBase.New(Stream, Name) EmitHeader() End Sub Public Sub New(ByVal Writer As TextWriter) MyBase.New(Writer) EmitHeader() End Sub Public Sub New(ByVal Writer As TextWriter, ByVal Name As String) MyBase.New(Writer, Name) EmitHeader() End Sub Protected Sub EmitHeader() 'Start tracing performance data MyBase.WriteLine("<trace>") End Sub Public Overloads Overrides Sub Write(ByVal Message As String) If msbBuffer Is Nothing Then msbBuffer = New StringBuilder() End If msbBuffer.Append(Message) End Sub Public Overloads Overrides Sub WriteLine(ByVal Message As String) If Not (msbBuffer Is Nothing) Then Message = msbBuffer.ToString & Message msbBuffer = Nothing End If EmitMessage(Message) End Sub Protected Sub EmitMessage(ByVal Message As String) 'Write performance data Dim objNow As DateTime = New System.DateTime().Now Dim objCalledFrom As New StackFrame(4) MyBase.WriteLine("<entry>") 'Timing data With objNow MyBase.WriteLine(CreateTag("time",.ToLongTimeString() & "." _ &.Millisecond.ToString)) MyBase.WriteLine(CreateTag("message", Message)) End With 'Caller data With objCalledFrom.GetMethod MyBase.WriteLine(CreateTag("method",.DeclaringType.FullName & "." _ &.Name)) End With 'Thread data MyBase.WriteLine(CreateTag("thread", Thread.CurrentThread.Name)) 'Finish log entry MyBase.WriteLine("</entry>") End Sub Protected Function CreateTag(ByVal TagName As String, _ ByVal TagContents As String) As String 'Return an XML tag Return "<" & TagName & ">" & TagContents & "</" & TagName & ">" End Function Public Overrides Sub Flush() 'Flush any remaining information to file If Not (msbBuffer Is Nothing) Then EmitMessage(msbBuffer.ToString) msbBuffer = Nothing End If 'Don't forget to chain to MyBase MyBase.Flush() End Sub Public Overrides Sub Close() 'Finish tracing performance data MyBase.WriteLine("</trace>") Me.Flush() 'Don't forget to chain to MyBase MyBase.Close() End Sub End Class
Using this trace listener is simplicity itself. See the code in Listing 6-13 for an example that writes the trace information to a file called Performance.xml. Notice that as it stands, this listener will hear all trace information emitted from anywhere in your application. You might want to restrict the listener to recording only performance data ”for instance, listening only to procedure entries and exits. To do this, you could establish some special prefix to the trace message, and then this listener can be told to ignore any trace message without this prefix. Alternatively, you can use the custom trace listener directly without adding it to the collection of trace listeners.
Imports System.IO 'Activate the custom trace listener and its output file stream Dim objPerformOutput As Stream = File.Create("Performance.xml") Dim objPerformRecorder As New TimerTraceListener(objPerformOutput) Trace.Listeners.Add(objPerformRecorder) 'Add this statement at the start of every monitored procedure Trace.WriteLine("Entering procedure") 'Add this statement at the end of every monitored procedure Trace.WriteLine("Leaving procedure") 'Add these statements when closing the custom trace listener objPerformRecorder.Flush() objPerformRecorder.Close()
To see some example performance diagnostics produced by this custom trace listener, look at the XML in Listing 6-14. This listing shows just two trace entries, the first written upon entering a procedure and the second produced when exiting the same procedure.
<trace> <entry> <time> 17:06:01.861 </time> <message> Entering procedure </message> <method>ConsoleAndText.Module1.Main</method> <thread></thread> </entry> <entry> <time> 17:06:01.907 </time> <message> Leaving procedure </message> <method>ConsoleAndText.Module1.Main</method> <thread></thread> </entry> </trace>
Once your application is producing and recording tracing information, the next step is to control the tracing process and the amount of diagnostic information produced. This is necessary because if you emit and record all of your diagnostic information all of the time, you'll find that your application is degraded in performance and your support team will suffocate under a huge pile of mostly useless information. Trying to find the significant application issues in a giant haystack of tracing information is almost impossible, especially if your application is large and/or distributed.
You've already seen that you can control the production of all tracing information at build time with the TRACE conditional compilation flag. This is, however, a single on/off decision; either you see all of the tracing information or you see none of it. To control the tracing process at a more granular level, you need to use one or more trace switches.
There are two predefined trace switch classes, both of which are in the System.Diagnostics namespace. The first is the TraceSwitch class, which gives you up to five trace levels to control the production of trace information. The second is the BooleanSwitch class, which gives you just two trace settings (on and off). The major benefit these two switch classes give you is the ability to specify several different tracing levels at runtime without recompiling your application. You can also define a custom trace switch if you want to add to, or extend, the standard trace switch functionality.
The BooleanSwitch class has an Enabled boolean property that can be set either in code, from a registry or other setting, or by using an application configuration file. Setting it to 1 or above returns true ; setting it to 0 or not setting it returns false . The code in Listing 6-15 shows a boolean switch being created and set to show all trace messages. Then it shows you how to test the property before writing a trace message.
'Create switch for controlling tracing in hypothetical component and set 'the boolean for this switch - setting could come from registry or config file Private bswTraceOutput As New BooleanSwitch("MyAppTracing", "Test boolean switch") bswTraceOutput.Enabled = True Public Sub Test 'Show whether the BooleanSwitch is enabled or disabled If bswTraceOutput.Enabled Then Trace.WriteLine(bswTraceOutput.DisplayName & " is enabled") Else Trace.WriteLine(bswTraceOutput.DisplayName & " is disabled") End If End Sub
Whereas the BooleanSwitch is either on or off, the TraceSwitch class is more flexible and supports five possible switches, as listed in the TraceLevel enumeration. Table 6-1 shows the supported values.
You can set the level of a trace switch either in code, from a registry or other setting, or by using an application configuration file. Notice that the higher levels assume the lower levels, so a setting of Warning would also show Error trace messages, and Verbose would show all trace messages. The code in Listing 6-16 shows a trace switch being created and set to show all trace information with a level of Warning or higher. Then it shows you two different ways of testing the trace switch's level before writing a trace message.
'Create switch for controlling tracing in hypothetical component and set 'trace level for this switch - setting could come from registry or config file Private tswTraceControl As New TraceSwitch("SwitchTrace", "Test trace switch") tswTraceControl.Level = TraceLevel.Warning Public Sub Test 'Either check the TraceError, TraceWarning, TraceInfo 'or TraceVerbose properties If tswTraceControl.TraceError Then Trace.WriteLine("Trace only shows if traceswitch is set to show errors") End If 'Or check the Level property against the TraceLevel enumeration If tswTraceControl.Level = TraceLevel.Warning Then Trace.WriteLine _ ("Trace shows if traceswitch is set to show warnings or errors") End If End Sub
You can create a custom trace switch by inheriting the TraceSwitch class. For instance, you might want to create custom tracing levels, maybe one for performance data, one for error information, and so on.
To demonstrate the creation of a custom trace switch, I've created one that adds extra information to any trace message and removes the task of checking the trace switch's trace level before writing the message. Before you look at the code for this trace switch, look at Listing 6-17 to see how you would use this switch.
Private AppTrace As New TraceSwitchCustom("AppTrace", "A custom trace switch") Public Sub Test() 'Show a trace information message AppTrace.MessageInfo("Trace information message", _ "This is a verbose version of the trace information") 'Show a trace warning message AppTrace.MessageWarning("Trace warning message", _ "This is a verbose version of the trace warning") 'Show a trace error message AppTrace.MessageError("Trace error message", _ "This is a verbose version of the trace error") End Sub
As you can see, this class is designed to avoid having the developer mess around with either trace levels or code dealing with extra trace diagnostics. The code in Listing 6-18 shows how such a trace switch class might be implemented. All trace messages are funneled through to the ControlTraceOutput procedure, where extra trace diagnostics such as the trace originating procedure and the date and time of the trace message are added.
Public Class TraceSwitchCustom : Inherits TraceSwitch Sub New(ByVal DisplayName As String, ByVal Description As String) 'Chain call to base class, then show that tracing has started MyBase.New(DisplayName, Description) ControlTraceOutput(TraceLevel.Info, Me.DisplayName & _ " trace listener created - trace level is " & Me.Level.ToString, "", 1) End Sub Protected Overrides Sub OnSwitchSettingChanged() 'Show that switch setting has changed If Me.TraceInfo Then ControlTraceOutput(TraceLevel.Info, Me.DisplayName & _ " trace level is now " & Me.Level.ToString, "", 1) End If End Sub Public Sub MessageError(ByVal Message As String, _ ByVal VerboseMessage As String) 'Show trace error message if errors are switched on If Me.TraceError Then ControlTraceOutput(TraceLevel.Error, Message, VerboseMessage, 2) End If End Sub Public Sub MessageWarning(ByVal Message As String, _ ByVal VerboseMessage As String) 'Show trace warning message if warnings are switched on If Me.TraceWarning Then ControlTraceOutput(TraceLevel.Warning, Message, VerboseMessage, 2) End If End Sub Public Sub MessageInfo(ByVal Message As String, ByVal VerboseMessage As String) 'Show trace information message if information messages are switched on If Me.TraceInfo Then ControlTraceOutput(TraceLevel.Info, Message, VerboseMessage, 2) End If End Sub Private Sub ControlTraceOutput(ByVal MessageLevel As TraceLevel, _ ByVal Message As String, _ ByVal VerboseMessage As String, _ ByVal StackDepth As Int16) 'Validate parameters supplied by caller If Message Is Nothing Then Message = "" If VerboseMessage Is Nothing Then VerboseMessage = "" 'Add system date/time to the trace message Dim strDateTime As String = New System.DateTime().Now.ToString 'Add originating module/procedure name to the trace message '(catch any stackframe error, probably a permission problem) Dim strTraceSource As String Try Dim objStackFrame As New System.Diagnostics.StackFrame(StackDepth) strTraceSource = objStackFrame.GetMethod.DeclaringType.FullName & _ "." & objStackFrame.GetMethod.Name Catch strTraceSource = _ "unknown procedure (stackframe call failed - check permissions)" Finally Trace.WriteLine _ (MessageLevel.ToString & " message at " & strDateTime & _ " from " & strTraceSource, Me.DisplayName) End Try 'Write augmented trace message Trace.Indent() Trace.WriteLine(Message) 'Emit verbose trace message if allowed and supplied If Me.TraceVerbose And VerboseMessage.Length > 0 Then Trace.Indent() Trace.WriteLine(VerboseMessage) Trace.Unindent() End If 'Finish message Trace.Unindent() Trace.Flush() End Sub End Class
Once your application is in testing or in production, the next step is to have runtime control over the tracing process and the amount of diagnostic information produced. This is necessary because you usually don't need to produce copious amounts of tracing information unless your testers or your end users are actually seeing a problem. During normal everyday use, you probably want to switch off most of the instrumentation to improve performance and to avoid generating useless information.
Though you can recompile your application to change its tracing behavior, it's much easier to do this with an application configuration file. A configuration file allows you to specify runtime decisions about adding and removing trace listeners, changing the level of trace switches, turning boolean switches on and off, and finally redirecting assertion failures to log files rather than message boxes. Together, these capabilities allow you to increase or decrease the amount of tracing information produced by your application, without actually having to recompile the application.
An application configuration file always resides in the same folder as its application, and it has to be named in the format MyApp .exe.config, where MyApp is replaced by the name of the executable. This text file must be in XML. The following sections discuss the XML formats used to control various aspects of application tracing.
The application configuration file allows you to add and remove trace listeners at runtime. This is important because it affects the performance of your application. You probably want to have all of the trace listeners removed during normal operation in a live environment. Once a problem appears, you can change the configuration file to reinstate one or more of the listeners. The XML in Listing 6-19 shows how to add a TextWriter trace listener and remove the default trace listener using your application's configuration file.
<configuration> <system.diagnostics> <trace autoflush="true"> <listeners> <add name="MyListener" type="System.Diagnostics.TextWriterTraceListener" initializeData="C:\MyListener.log"/> <remove name="Default"/> </listeners> </trace> </system.diagnostics> </configuration>
After you've played around with this for a while, you may notice a couple of peculiarities . The first oddity is that the documentation is wrong about the format of the type element. If you specify the assembly name System after the trace listener as the documentation shows, you'll encounter an error. It seems as though this functionality was changed after the second beta, but the documentation wasn't updated. If you do want to specify the assembly, you have to identify it completely, with something like System , Version =1.0.3300.0 , Culture =neutral , PublicKeyToken =B77A5C561934e089 . The second oddity is that the autoflush doesn't always seem to work. Although the log file is always created, forcing the trace information to be written to the log file sometimes requires a Trace.Flush and a Trace.Close before you close your application.
The application configuration file also allows you to change the sensitivity level of your trace switches without recompiling your software. For instance, during development and unit testing, you might want to show all trace messages, whether they're informational messages, warnings, or errors. Once the application has reached system testing, you might want to show just trace warnings and errors. Finally, when your application reaches production, you could show just trace errors. Listing 6-20 shows the XML needed to set a database trace switch to show only trace errors and a component trace switch to show all errors. The numbers refer to the levels discussed earlier in the section on trace switches.
<configuration> <system.diagnostics> <switches> <add name="DatabaseSwitch" value="1"/> <add name="ComponentSwitch" value="4"/> </switches> </system.diagnostics> </configuration>
It's important to realize that, unlike the XML shown in Listing 6-19, this doesn't actually create the trace switches ”it just sets the level of trace switches already defined in your code.
The boolean switch activation operates in just the same way as the trace switch activation just discussed, but of course you only have two levels with which to play. The XML in Listing 6-21 shows how to disable a boolean switch using the application configuration file.
<configuration> <system.diagnostics> <switches> <add name="BoolSwitch" value="0"/> </switches> </system.diagnostics> </configuration>
As discussed earlier in this chapter, assertions are used to warn the developer and support teams about runtime behavior that should never happen and assumptions that are being violated. These assertions are excellent for catching many bugs automatically and for verifying developer assumptions. Whenever an assertion fails, a message box explaining the failure is shown to the developer.
The question is, what should happen with assertions when the application is promoted into production? First, if you want to keep all of the assertion checks, there's no benefit in showing each assertion failure to the end user via a message box. This is likely to prove confusing to most users and add absolutely nothing to their use of your software. Second, you might want to turn off assertions completely because all of those checks can create a serious drag on application performance. The thinking behind this is that if all of the assumptions and other checks were validated during development and testing, there's no need to waste time on them in production.
If you want to keep your assertion checks in production, you should add the XML in Listing 6-22 to the production version of your application's configuration file to redirect all assertion failures to the specified log file. This will prevent your end users from being assaulted with unfriendly message boxes.
<configuration> <system.diagnostics> <assert assertuienabled="false" logfilename="c:\log.txt"/> </system.diagnostics> </configuration>
If you want to turn off the assertion checks entirely once your application reaches production, you should use Debug.Assert (from the Debug class) rather than Trace.Assert . The two methods produce identical results, but all Debug class methods are automatically dropped during compilation of a release build. Please see the section titled "Using the Debug Class" later in this chapter for more details.
After such an intensive examination of VB .NET tracing and instrumentation, the following list presents a quick recap of what you've just learned about working with application tracing diagnostics:
Categorize your diagnostic information : Decide what tracing information is required and divide the output into error messages, warning messages, informational messages, and extra detail (verbose) messages. These categories match the predefined tracing levels that have already been discussed.
Add tracing code : Use the Trace class to add the required tracing code to your application.
Add trace listeners : Use predefined or custom TraceListener classes to define the trace message destination(s).
Add trace switches : Use the TraceSwitch and BooleanSwitch classes to specify when and which tracing information is shown.
Useruntime tracing control : Use your application's configuration file to control trace listeners, trace switches, and assertions at runtime.
I've spent a lot of time discussing the Trace class and its companions, but it also has an important counterpart in the Debug class.