Thursday, November 1, 2007

Debugging with the Fusion logger

If you've spent much time developing, you've probably run into this scenario. You're working along coding a new application. Everything runs on your machine. Then you hand it off to someone to test (that, or load it on the production server - let the users tell you what's wrong.) Unfortunately, the app crashes as soon as you attempt to start it. Looking in the Event Logs, you see generic .Net errors, but nothing that appears to help. Short of installing VisualStudio on the box in question, how do you track down the issue?

One place to start is the Fusion logs. For this demo, I've created a class library (MyClassLib) and a command-line app (MyConsoleApp.) The app makes a single method call into the library and then exits. Nothing interesting to see when everything works. If I delete MyClassLib.dll and run the application, I witness a rather unpleasant dialog


When an app closes in a violent manner, the first place to look is the computer's event logs. Unfortunately, the only entry for the app looks something like:

"Faulting application myconsoleapp.exe, version 1.0.0.0, stamp 47293d14, faulting module kernel32.dll, version 5.1.2600.3119, stamp 46239bd5, debug? 0, fault address 0x00012a5b."

So now we turn to the Fusion logs. The first step is to copy the Assembly Binding Log Viewer (fuslogvw.exe) from any machine with VS2005. Start it up; it looks something like this:


Click on the Settings button. In the dialog, select "Log bind failures to disk." Check the box to "Enable custom log path" and specify an already-existing folder (the app won't create it for you.)


Note: According to official documentation, you should be able to use the default log directory. In my experience, that never seemed to work.

With the logger set up I again attempt to run the application. Which again crashes. Going back to the Fusion log viewer, click Refresh. I now have a single entry


Clicking on the entry loads the details in Internet Explorer (shown below.) If you look halfway down the log, you'll see the reference to MyClassLib. Near the end, you'll see the various locations it searched for the file. Now it's a simple matter of finding a copy of my dll and placing in the search path.



*** Assembly Binder Log Entry (10/31/2007 @ 10:14:45 PM) ***

The operation failed.
Bind result: hr = 0x80070002. The system cannot find the file specified.

Assembly manager loaded from: C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorwks.dll
Running under executable C:\temp\testcode\MyConsoleApp\bin\Release\MyConsoleApp.exe
--- A detailed error log follows.

=== Pre-bind state information ===
LOG: User = SH\pgoins
LOG: DisplayName = MyClassLib, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null
(Fully-specified)
LOG: Appbase = file:///C:/temp/testcode/MyConsoleApp/bin/Release/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = MyConsoleApp.exe
Calling assembly : MyConsoleApp, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null.
===
LOG: This bind starts in default load context.
LOG: No application configuration file found.
LOG: Using machine configuration file from C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\config\machine.config.
LOG: Policy not being applied to reference at this time (private, custom, partial, or location-based assembly bind).
LOG: Attempting download of new URL file:///C:/temp/testcode/MyConsoleApp/bin/Release/MyClassLib.DLL.
LOG: Attempting download of new URL file:///C:/temp/testcode/MyConsoleApp/bin/Release/MyClassLib/MyClassLib.DLL.
LOG: Attempting download of new URL file:///C:/temp/testcode/MyConsoleApp/bin/Release/MyClassLib.EXE.
LOG: Attempting download of new URL file:///C:/temp/testcode/MyConsoleApp/bin/Release/MyClassLib/MyClassLib.EXE.

LOG: All probing URLs attempted and failed.

4 comments:

  1. Great info! Maybe I'll be brave enough to use it sometime... or I could just IM you with the event log entry...

    "Faulting application myconsoleapp.exe, version 1.0.0.0, stamp 47293d14, faulting module kernel32.dll, version 5.1.2600.3119, stamp 46239bd5, debug? 0, fault address 0x00012a5b."

    I'm sure a super-genius like you could figure out those dll/hex numbers and tell me exactly what's wrong.

    ReplyDelete
  2. You can deduce the problem from the hex values, but it requires you to place them in context. For me, they mean "Go look at the Fusion logs." For you, they mean "Problem between keyboard and chair." :)

    ReplyDelete
  3. In a time of hex-address distress the only problem between my keyboard and chair is the wrong person is there!

    ReplyDelete
  4. Rework that a little...

    In a time of obscure hex address
    Application crash distress
    The only flaw 'tween keyboard and chair
    Is that the incorrect person is there

    That flows so much better :)

    ReplyDelete

Note: Only a member of this blog may post a comment.