Bugslayer

Unhandled Exceptions and Tracing in the .NET Framework 2.0

John Robbins

Code download available at:Bugslayer0507.exe(148 KB)

What Happened to My Thread!?
A Better Way
Tracing the New Way
Tracing Sample
More Tracing Improvements
Wrap Up
Tips

By now, you've certainly heard about the big changes coming in Visual Studio® 2005, but when it's time to move your code over it will be the small things that trip you up. In this column, I want to cover two of the many excellent changes that you could easily overlook as you make the move to the new runtime and development tools. Don't get me wrong. I don't mean to make the transition sound dangerous. The truth is, your ported code will probably work just great with nothing more than a recompile. But there are things you should know. When you finish reading, you should also check out the "What's New" sections in the documentation.

The first change I'll talk about is how the common language runtime (CLR) in the Microsoft® .NET Framework 2.0 now handles unhandled exceptions. Then I'll discuss some of the excellent enhancements to the tracing system so you can get the best information from the field.

What Happened to My Thread!?

In native Windows® development, the SetUnhandledExceptionFilter API from KERNEL32.DLL makes it trivial for the OS to notify you when any thread in your application has an unhandled exception. If you've been reading Bugslayer over the years, you'll know I've spent my share of ink on using and extending the magic SetUnhandledExceptionFilter.

When I turned to .NET development, it looked like the AppDomain.UnhandledException event had the same sort of functionality. If you register a delegate with this event, the common language runtime notifies you that an unhandled exception occurred, but there's a serious twist. What happens after you return from your delegate depends on the thread type.

To demonstrate the exception-handling problems in the .NET Framework 1.x, download and compile the ConsoleExceptions program (included with this month's code download) in Visual Studio .NET 2003. The program takes two parameters; the first is a "y" to install an AppDomain.UnhandledException delegate, or an "n" to use the default handlers. The second is the thread type in which you want to cause an exception ("m" for the main thread, "t" for a managed thread, "p" for a pool thread, and "g" for the garbage collector finalizer thread).

Running ConsoleException.exe with the parameters "n m" brings up the just-in-time (JIT) debugging dialog and gives you an opportunity to debug the application in the managed debugger of your choice. While I did not include an option to create a native thread from a C++ DLL in ConsoleException, you would see the exact same behavior as you get from a crash in the main thread.

Things get more interesting if you specify a crash in any other type of thread in ConsoleException. For example, if you use the command-line parameters "n t" to cause an exception in a managed thread, you won't see a JIT debugging dialog. In fact, instead you'll see the call stack from the default exception filter in the console, followed by Console.WriteLine output indicating that the finally block in Main executed, and "Done!" to indicate the application ran to completion.

When I first saw this behavior, which is the same for the garbage collector and all pool threads as well, my eyes popped out of my head and bounced off my monitor. What's happening is the CLR is silently killing those threads! Interestingly, there is an undocumented option to have the JIT debugger pop up when an unhandled exception occurs on threads other than the main thread. If you set the upper 6 bytes of the DWORD value DbgJITDebugLaunchSetting to 0xFFFFFF in HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\.NETFramework, that tells the CLR to bring up the debugger. Set the low byte to the default 0x02 to spawn the debugger specified in the DbgManagedDebugger value in the same key.

After setting the DbgJITDebugLaunchSetting to 0xFFFFFF02, and passing "n t" as the command-line arguments to ConsoleException, you'll see the fine JIT debugging dialog. Before you press "Yes" to debug ConsoleException, take a peek at the console window in which ConsoleException is running. You'll see something very odd. You'll see "Done!", indicating that the application has ended and you'll see the blinking cursor at the prompt. Of course, if you press "Yes" on the JIT debugging dialog, you'll get an error stating that the application is invalid. If you haven't guessed, the rest of your application keeps running on its merry way when a thread is blocked waiting in the JIT debugging dialog.

If you do add a delegate to AppDomain.UnhandledException, the CLR will notify you that there's been an exception so you can at least log that fact and possibly kill the process. The UnhandledExceptionEventArgs parameter has a read-only Boolean property, IsTerminating, that is true if the application is ending. This indicates the exception came out of the main thread or a Win32® native thread. As you can guess, a value of false in IsTerminating indicates the exception came from one of the other types of threads.

A Better Way

The great news about the .NET Framework 2.0 is that unhandled exceptions, no matter where they come from, now cause termination of the app. You also have the chance to debug the unhandled exception if you have a JIT debugger installed. If you haven't installed an AppDomain.UnhandledException delegate and you're using multiple threads in your console or Windows Forms applications, you'll definitely want to add one when you port your code to the .NET Framework 2.0 because you may have been silently losing threads all along.

I can't thank the Redmondtonians enough for finally changing this design. While a breaking change from the behavior in the .NET Framework 1.x, this will definitely lead to better applications because you'll immediately know when there's a problem (if you really want to keep the old behavior, there is a configuration switch that will let you). While a mini dump and Son of Strike (SOS) is the next best thing to being there when your app takes a dive, getting those giant full-memory dumps can be a problem. In those cases, judicious use of tracing can save the day. Fortunately, the .NET Framework 2.0 has a bunch of great tracing enhancements.

Tracing the New Way

The number-one sentiment about tracing is that it's very cool that you set a TraceSwitch externally in the config file, but getting the TraceSwitch to reread the config file while the app is running is a big concern. In the .NET Framework 1.x, you have to manually do all the work yourself. But in the .NET Framework 2.0, the Trace object has a static method, Refresh, that will force a reread of the configuration file and update any trace switches as appropriate.

Instead of everyone writing their own file change watcher, I whipped up a little class you can drop into your apps to get the TraceSwitch updates easily (see Figure 1). The only hitch is that Visual Studio 2005 console and Windows Forms applications by default run inside a special named process, <<em>Program Name>.VSHOST.EXE, which allows for faster managed debugging.

/*----------------------------------------------------------------------- * MSDN Magazine - Bugslayer Column - John Robbins * A .NET Framework 2.0 class to refresh the TraceSwitch values whenever * app's configuration file changes. -----------------------------------------------------------------------*/ using System; using System.IO; using System.Text; using System.Threading; using System.Reflection; using System.Diagnostics; using System.Collections.Generic; namespace Bugslayer { /// /// A class that watches the application config file and refreshes all /// values. /// class ConfigTraceSwitchWatcher { // The file watcher itself. private FileSystemWatcher watcher; // The name of the configuration file for reference. private String appConfigFile; /// Creates the watcher for the config file. public ConfigTraceSwitchWatcher ( ) { appConfigFile = AppDomain.CurrentDomain.SetupInformation. ConfigurationFile.ToUpper().Replace(".VSHOST", ""); Initialize ( ); } /// Creates the watcher for the file. /// The full path to watch. public ConfigTraceSwitchWatcher ( String fileName ) { appConfigFile = fileName; Initialize ( ); } /// Shuts off all configuration monitoring. public void Close ( ) { // Clear the notifications. watcher.EnableRaisingEvents = false; watcher = null; appConfigFile = null; } // The common initialization. private void Initialize ( ) { Debug.Assert(appConfigFile != null, "appConfigFile != null"); Debug.Assert(appConfigFile.Length > 0, "appConfigFile.Length > 0"); if ((null == appConfigFile) || (appConfigFile.Length == 0)) { throw new ArgumentException ( "appConfigFile" ); } // Set the directory to watch and only watch for writes String path = Path.GetDirectoryName ( appConfigFile ); watcher = new FileSystemWatcher ( path ); watcher.NotifyFilter = NotifyFilters.LastWrite; // Set up the event handlers. Make sure to watch // changes made to file, including creation and deletion. watcher.Changed += new FileSystemEventHandler ( watcher_Changed ); watcher.Deleted += new FileSystemEventHandler ( watcher_Changed ); watcher.Created += new FileSystemEventHandler ( watcher_Changed ); // Let fly. watcher.EnableRaisingEvents = true; } void watcher_Changed ( object sender , FileSystemEventArgs e ) { // Check to see if this is the real application config. if (0 == String.Compare (appConfigFile, e.FullPath, true, Thread.CurrentThread.CurrentCulture)) { // Can this get any simpler? Trace.Refresh( ); } } } }

Tracing Sample

When I first developed ConfigTraceSwitchWatcher, I saw to my dismay that my App.Config files were copied to both <<em>Program Name>.EXE.CONFIG and <<em>Program Name>.VSHOST.EXE.CONFIG. The good news is that the <<em>Program Name>.VSHOST.EXE that is used when debugging uses the <<em>Program Name>.VSHOST.EXE.CONFIG for startup, but after that, all the configuration information is read from the proper <<em>Program Name>.EXE.CONFIG. That's why you see the code to strip out ".VSHOST" in the ConfigTraceSwitchWatcher constructor.

The code to ConfigTraceSwitchWatcher is in the TraceRefreshDemo program included with this month's source code so you can play with it interactively. If you don't want to debug using the Visual Studio hosting process, you can go into the Debug property page and uncheck the Enable the Visual Studio hosting process. Based on experiments with builds prior to Beta 2, managed debugging is definitely faster with the Visual Studio hosting process enabled. So, with almost no code changes at all, you can get the benefits of ConfigTraceSwitchWatcher in your existing app.

Another new set of classes that you can easily take advantage of are the new TraceListener-derived classes. The first of these, WebPageTraceListener, mimics my ASPTraceListener class, which I talked about when I first covered .NET in October 2001 (see Bugslayer: Handling Assertions in ASP .NET Web Apps), and puts any System.Diagnostics.Trace.Write* output on the page. The WebPageTraceListener class does not appear automatically in the Trace.Listeners collection, so if you want to use it, you'll need to either add WebPageTraceListener to the collection programmatically, or add it through the section of your Web.config. For more information, see "Walkthrough: Integrating ASP.NET Tracing with System.Diagnostics Tracing" in the Visual Studio 2005 Help.

On a side note, part of the motivation for the October 2001 column was to provide a functional assertion for ASP.NET applications. Now that your Edit-Compile-Debug cycle for your ASP.NET applications will be spent using the integrated Web server rather than IIS, you'll get to see the DefaultTraceListener assertion message box in all its stack trace glory with nothing extra on your part. There's still no assertion that will work while running inside IIS, so you still might want to consider my ASPTraceListener. But being able to see most of your assertions during coding and unit testing is a huge boon for productivity.

For those of you building console applications, you can see your tracing directly in the console window with the new ConsoleTraceListener. The default is for the ConsoleTraceListener to send its output to standard output, but you can specify that the output go to standard error instead by passing false to the constructor. If you're into delimited output, the new DelimitedTraceListener will separate the output with semicolons by default. Of course, you can change the character by setting the DelimitedListTraceListener.Delimiter property.

While tracing to a raw text file is helpful, I can't count the number of teams that have implemented their own XML output TraceListener so they can add some more useful data to the tracing output. If you wanted one, but didn't have the time to write it, you can now use Microsoft-supplied XmlWriterTraceListener.

Figure 2 is an example of the output. Microsoft has not yet released the schema, but looking at the output (which at the time of this writing is not well-formed XML as there are multiple root elements), you see that there's more interesting data than just simple strings in there.

0 3 0 8 TESTBOX Hello from the first string in the output!! 0 3 0 8 TESTBOX About to go into loop...

The tracing enhancements I've been talking about require either very minor code changes or tweaking your application's configuration file. However, you can see from the output of the XmlWriterTraceListener, there are a few more changes to tracing in the .NET Framework 2.0. These changes help solve a problem that the existing System.Diagnostics.Trace object exhibits when you start working on larger applications.

More Tracing Improvements

As it stands in the .NET Framework 1.x, there's only one Trace object that's global to the application domain. For most applications that's fine because you can add different output options through TraceListener-derived classes added to the Trace.Listeners collection. However, as you move into larger industrial-strength applications, the global, one-size-fits-all nature of the Trace object becomes a hindrance. While you can designate TraceSwitch options to control output, if you want to see only three assemblies tracing (of the multitude of assemblies you may have in your application), all that output still goes to the same TraceListeners so you will have tons of output to sort through.

Another problem with the existing Trace object in larger applications is that the output is limited to just the string passed to Trace.Write*. In real-world apps, many times, such as when tracing into error handling code, you want to add lots of additional output, such as the call stack, process information, thread information, and so on. While you could programmatically add that data into every place where you think you might need it in your trace output, it would be much better if you could dynamically change the data output in the configuration file.

With the new TraceSource class, Microsoft has pushed the Trace object down a level. A TraceSource has the same basic capabilities as the Trace object in that the TraceSource offers methods for tracing as well as Listeners properties so you can have extensible output. Now if you want specific tracing for those multiple assemblies, you'd simply configure each assembly's TraceSource in the application configuration file. You can add the specific TraceListeners to each assembly's TraceSource so that all output will be independent of the others, making analysis a lot easier. Additionally, TraceSource supports the TraceSwitch classes that make it easy to control the level of output: Error, Warning, Informational, and Verbose.

Instead of writing about all the new pieces, just showing you the code will be worth thousands of words. Figure 3 uses the new TraceSource in a programmatic fashion along with plenty of comments about the output and features. You should read this as it wasn't until I wrote the code in Figure 3 that the awesome new tracing features made sense.

using System; using System.Text; using System.Diagnostics; using System.Collections.Generic; class Program { static void ShowAllTraceMethods ( TraceSource trc ) { // The simplest method. Notice it takes parameters, which is a // big improvement over the Trace object. trc.TraceInformation ( "The simplest trace method with {0}{1}" , "params" , "!" ); // The method to trace an event based on the TraceEventType enum. trc.TraceEvent ( TraceEventType.Error , 100 , "Pretend error!" ); // The method to make dumping out data easy. trc.TraceData ( TraceEventType.Information , 50 , "Some" , "pretend" , "data." ); // The method to record a transfer. This method is primarily for // the XmlWriterTraceListener. See the column text for more // discussion. trc.TraceTransfer ( 75 , "What was transfered?" , new Guid ("7b5fcdbc-913e-43bd-8e39-ee13c062ecc3") ); } static void Main ( string[] args ) { // Create the TraceSource for this program. Like the Trace // object, the TraceSource.Listeners collection starts out with // the DefaultTraceListener. TraceSource trc = new TraceSource ( "HappySource" ); // Set the switch level for this TraceSource instance so // everything is shown. The default for TraceSource is to *not* // trace. The default name of the switch is the same as the // TraceSource. You'll probably want to be sharing Switches across // TraceSources in your development. trc.Switch.Level = SourceLevels.All; // Trace to show the default output. ShowAllTraceMethods ( trc ); // The TraceListener class has a very interesting new property, // TraceOutputOptions, which tells the TraceListener the additional // data to automatically display. trc.Listeners[ "Default" ].TraceOutputOptions = TraceOptions.Callstack | TraceOptions.DateTime | TraceOptions.ProcessId | TraceOptions.ThreadId | TraceOptions.Timestamp; // Now all the trace calls in the Debug Output window will show // all the data included in the TraceOutputOptions. ShowAllTraceMethods ( trc ); // Filtering allows you to apply a limiter to the TraceListener // directly. That way you can turn on tracing, but apply more // smarts to the actual output so you can better separate the // wheat from the chaff on a production system. EventTypeFilter evtFilt = new EventTypeFilter ( SourceLevels.Error ); // Apply the filter to the DefaultTraceListener. trc.Listeners[ "Default" ].Filter = evtFilt; // The only output in the Debug Output window will be from the // TraceEvent method call in ShowAllTraceMethods. ShowAllTraceMethods ( trc ); trc.Flush ( ); trc.Close ( ); } }

After I'd written that code, I ran across a wonderful blog entry (A Tracing Primer - Part I) from Mike Rousos, a member of the BCLTeam, talking about the TraceSource. The blog had a graphic that showed where the various classes fit together. For those of you who are graphical thinkers, I took Mike's idea and expanded it so you could see how a trace flows through the new tracing system.

Figure 4 shows three different TraceSource instances in use by an app. When a Trace* method is called, it checks the Switch-derived class in the TraceSource.Switch property to see if the condition on the Trace* method matches. If not, nothing is traced. Notice that a Switch class can be shared between TraceSource instances (see B and C in the diagram). If the Switch-derived condition is met, the TraceSource loops through its Listeners collection calling the appropriate TraceListener.Trace* method. (In the .NET Framework 2.0 documentation you'll see that the TraceListener class has numerous new properties and methods.)

Figure 4** Data Flow of TraceSource to Output **

If the individual TraceListener class has a TraceFilter instance in the TraceListener.Filter property, before any output is sent, the TraceListener checks to see if TraceFilter.ShouldTrace returns true. If it does not, no output is sent. If ShouldTrace returns true, the output is sent to that TraceListener's internal writing method.

In Figure 4, TraceSource instance B has a single TraceListener instance called X1 set in its TraceListeners collection and TraceSource C has a single TraceListener called Y1. However, the TraceSource objects are sharing a Switch 2, so any initial matching on the TraceSource.Trace* methods for B or C will be filtered identically. In the case of the two TraceListeners, they both share a filter, Filter 2, so any filtering will apply to both.

At the top of Figure 3, the ShowAllTraceMethods calls each of the methods in a TraceSource instance dedicated to tracing. The first method, TraceInformation, is for the simplest tracing, and after I talk about the other methods, you probably won't want to use it for your tracing as it has no flexibility for controlling output externally. The main method you'll want to use is TraceEvent as it allows you to assign a TraceEventType enumeration to indicate the level of tracing. The second parameter is the numeric identifier for the trace. With that parameter you either uniquely identify tracing, or assign a specific value to a class to help identify tracing output at a glance. There are three overloads to TraceEvent, but the big news is that one takes variable-length parameters so you can pass a formatting string and get your data displayed nicely in the trace.

The TraceData method accepts the trace identifier as well, but its main purpose in life is to allow you to pass either an object array or multiple parameters so the trace output shows them separated by commas. If you are dealing with data objects whose ToString method does the heavy lifting, the TraceData call can be your dependable friend. In the broader scheme of things, you'll nearly always use TraceEvent.

The final method, TraceTransfer, was designed to work hand in glove with the XmlWriterTraceListener. If you look back at the output of XmlWriterTraceListener in Figure 2, you might have noticed a Correlation element with an ActivityID attribute that looks like a GUID. TraceTransfer sets the internal GUID that the XmlWriterTraceListener will use until the next time a call to TraceTransfer sets a new GUID. You can assign a GUID to major activities in your application, such as login handling, so you can quickly scan the XmlWriterTraceListener output looking for logical operations in your tracing.

I'm willing to bet that only the largest applications will use TraceTransfer and the ActivityID. That's because the first parameter of both the TraceEvent and TraceData methods is a TraceEventType, and it's worth mentioning how much this has grown in the .NET Framework 2.0. In the .NET Framework 1.x, you were limited to Error, Warning, Info, and Verbose with a TraceSwitch. Figure 5 shows all the values of the TraceEventType enum and what they are for. As you can see, Start, Stop, Resume, and Transfer are all called activity types. Since one of the primary uses of tracing is to determine which operations occurred and the order in which they occurred, these new tracing events make that extremely easy. To see just the activity tracing, you can set the TraceSource.Switch.Level to SourceLevels.ActivityTracing.

While programmatically manipulating TraceSource instances is possible, as shown back in Figure 3, the real action is in manipulating the tracing from the application's configuration file. Figure 6 shows the App.config of the ConfigTraceSource program included with this month's source code. The program has two TraceSource instances, HappySource and GiddySource. The sources element is where you configure the individual TraceSource instances in a source element for each instance you want to configure. The two required attributes to the source element are the self-explanatory name and switchName. By associating a Switch instance with the TraceSource, you can control the output for the TraceSource instance. Keep in mind that Switch instances can be shared across multiple TraceSource instances.

Underneath the source element, you can specify any TraceListeners you want to associate with that TraceSource. You can add and remove any items from the TraceSource.Listeners property as well as dynamically create new TraceListeners directly from the configuration file, just like you can in the .NET Framework 1.x.

What's most interesting in Figure 6 is the sharedListeners element where you can add TraceListener instances to all TraceSource instances in the application. In the XmlWriterTraceListener added in Figure 6, I also show how to apply a TraceFilter to a TraceListener. The new traceOutputOptions attribute allows you to specify the TraceOptions you want applied to the TraceListener.

While I added that filter to the TraceListener being shared across all TraceSource instances, you can also add those TraceFilters to TraceListeners you add to an individual TraceSource instance.

The last piece of Figure 6 is the switches element, where you configure individual Switch instances. The only difference in the switches element in the .NET Framework 2.0 from the .NET Framework 1.x is that the value attribute can now take string values that are passed to the switch constructor to set the value.

As you can see, the amount of control that you have over your tracing in the configuration with the .NET Framework 2.0 is simply amazing. The icing on the cake is the new ability in the .NET Framework 2.0 to tell you the exact line in the configuration file that's not correct so those of us who have spent hours pulling our hair out looking for problems in our configuration file can now start growing some of it back.

Wrap Up

While it's long overdue, the "Dude! Where did my thread go?" fix makes the .NET Framework 2.0 a mandatory upgrade in my book. All the working set reductions and performance boosts are secondary. In fact, I've been moving my heavily multithreaded applications over to the .NET Framework 2.0 for testing even if they are due to ship on the .NET Framework 1.x just to take advantage of the fixed behavior.

Microsoft spent quite a while looking at different applications to see what folks needed. Of course, the documentation for Visual Studio 2005 Beta 2 says almost nothing about the new tracing capabilities so I knew you could use this information. As I was playing with the new tracing, I kept looking for features that have been left out, but I have yet to find any. That's a great sign!

Tips

Tip 69 As all good Bugslayers know, a symbol server is a mandatory tool in your development shops. Prior to Visual Studio 2005, getting the pesky _NT_SYMBOL_PATH environment variable setup was an accident waiting to happen. Symbol server is now drastically easier to set up. Simply go to the Options dialog, Debugging, Symbols property page. In the Symbol files location control, paste in the following string that specifies the location of the Microsoft public symbol server: https://msdl.microsoft.com/download/symbols For your own symbol servers, simply enter \\server\share where server and share are the names inside your network.

Tip 70 A good statistic to keep track of is the churn on your publicly accessible types, classes, methods, and properties between versions of your apps. This can help you pinpoint areas you need to test and alert you to potential breaking changes. The .NET team is obviously very concerned about this, so they produced a tool called LibCheck to generate those statistics. You can read more about it at Using reflection to List version to version assembly changes: Libcheck, one of the best tools ever!.

Send your questions and comments for John to  slayer@microsoft.com.

John Robbins is a cofounder of Wintellect, a software consulting, education, and development firm that specializes in .NET and Windows. His latest book is Debugging Applications for Microsoft .NET and Microsoft Windows (Microsoft Press, 2003). You can contact John at www.wintellect.com.