El TecnoBaúl de Kiquenet

Kiquenet boring stories

FUSLOGVW, Assembly Binding Log Viewer

Posted by kiquenet en 16 febrero 2011

ASSEMBLY PROBING, FUSION AND FUSLOGVW IN 5 MINUTES

Introduction

A couple of days ago I received the following mail:

Hi Bart,
I’m trying to add an install functionally that will just basically copy the whole CD content to a local C drive folder. Executing the launcher.exe in that local folder works fine but if I create a desktop shortcut that targets the launcher.exe produced a file not found error for cassinilight.dll. I was wondering if you have an idea in what location was the application looking for cassinilight.dll.  Any help is highly appreciated.

The short answer is really short: probing. Probing is the technique employed by the CLR’s assembly loader to find a dependent assembly based on searching for it in various folders. Strongly named assemblies (those you signed using an sn.exe generated public/private key pair) are being searched for in the GAC (and paths specified in codeBase configuration elements, see further; and the "standard locations"). Weakly named assemblies are also probed, by looking in the same folder as the application and in subfolders named after the dependent assemblies themselves. However, sometimes it’s not that easy and you really want to see what’s going on (a common problem is an assembly being loaded from the GAC while you have recompiled it to your bin\Debug folder in Visual Studio which leads to unexpected debugging results).

In this post, I’m showing you how to make a jumpstart with Fusion, assembly probing and the "Fusion log viewer" aka fuslogvw.exe. For the record, Fusion is the codename of the assembly loader component of the CLR which (you can still see this in the SSCLI source tree under sscli20\clr\src\fusion).

A faulty application

Right, let’s create a plain simple demo to illustrate the principle. It’s so simple it fits in one console window using "copy con" file generation:

The code is:

foo.cs (compile using csc /t:library foo.cs)
public class Foo
{
}

bar.cs (compile using csc /t:library /r:foo.dll bar.cs)
class Bar
{
   public static void Main()
   {
      new Foo();
   }
}

Now you should have two assemblies: foo.dll and bar.exe. Run the application, it should just run (although it doesn’t do anything useful, it doesn’t produce any errors either).

Time has come to make the app faulty. Create a subfolder called "oops" and move the foo.dll file to it. Now bar.exe will fail:

And guess what, you shouldn’t even read my blog to find out what’s wrong. The runtime is so kind to tell you to enable Fusion:

To enable assembly bind failure logging, set the registry value [HKLM\Software\Microsoft\Fusion!EnableLog] (DWORD) to 1.

Setting up Fusion

Redundant info maybe, but here are two ways to enable Fusion.

For modern developers – PowerShell

PS C:\Users\Bart> new-itemproperty -path HKLM:\SOFTWARE\Microsoft\Fusion -n EnableLog -t Dword -va 1

PSPath       : Microsoft.PowerShell.Core\Registry::HKEY_LOCAL_MACHINE\SOFTWARE\               Microsoft\Fusion
PSParentPath : Microsoft.PowerShell.Core\Registry::HKEY_LOCAL_MACHINE\SOFTWARE\               Microsoft
PSChildName  : Fusion
PSDrive      : HKLM
PSProvider   : Microsoft.PowerShell.Core\Registry
EnableLog    : 1

For command-line freaks – reg.exe

C:\temp>reg add HKLM\Software\Microsoft\Fusion /v EnableLog /t REG_DWORD /d 1
The operation completed successfully.

For UI lovers – regedit.exe

You should be able to find out yourself :-).

Analyzing the problem

Run bar.exe again after you’ve enabled Fusion. This time you get a realm of information:

The most interesting portion is the last part:

LOG: Attempting download of new URL file:///C:/temp/foo.DLL.
LOG: Attempting download of new URL file:///C:/temp/foo/foo.DLL.
LOG: Attempting download of new URL file:///C:/temp/foo.EXE.
LOG: Attempting download of new URL file:///C:/temp/foo/foo.EXE.

These are the locations where the system attempted to find the referenced assembly "foo". The "oops" folder isn’t there obviously, so the probing operation fails.

Now run fuslogvw.exe and you should see the following log information:

If you double-click on the last line, you’ll see the following in a browser window:

*** Assembly Binder Log Entry  (12/10/2006 @ 12:16:56) ***
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\bar.exe
— A detailed error log follows.
=== Pre-bind state information ===
LOG: User = Bart-PC\Bart
LOG: DisplayName = foo, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null
(Fully-specified)
LOG: Appbase = file:///C:/temp/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = bar.exe
Calling assembly : bar, Version=0.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/foo.DLL.
LOG: Attempting download of new URL file:///C:/temp/foo/foo.DLL.
LOG: Attempting download of new URL file:///C:/temp/foo.EXE.
LOG: Attempting download of new URL file:///C:/temp/foo/foo.EXE.
LOG: All probing URLs attempted and failed.

Since there’s no application configuration file to specify probing locations, the default probing process is used, effectively looking in the same folder as the application (seeAppbase) and in a subfolder with the assembly name (without the extension, i.e. Appbase\AssemblyName, in our example c:\temp\foo). All logs end up in the IE temporary files cache, but you can override this in fuslogvw (or by setting registry entries):

where "c:\temp" is set in the LogPath REG_SZ value in the Fusion registry key. The logging info will end up in a subfolder called "NativeImage":

Setting a custom probing path

You can drive the probing mechanism by specifying probing paths in a configuration file. So create the following bar.exe.config file in the bar.exe folder (c:\temp on my system):

<?xml version="1.0"?>
<configuration>
   <runtime>
      <assemblyBinding xmlns="urn:schemas-microsoft-com:asm.v1">
         <probing privatePath="oops" />
      </assemblyBinding>
   </runtime>
</configuration>

Now bar.exe works fine again:

If you configure Fusion to log all binds to disk, like this:

you’ll see log entries appear after re-running the bar.exe applicatin again:

This time with the following logging info:

*** Assembly Binder Log Entry  (12/10/2006 @ 13:01:05) ***
The operation was successful.
Bind result: hr = 0x0. The operation completed successfully.
Assembly manager loaded from:  C:\Windows\Microsoft.NET\Framework\v2.0.50727\mscorwks.dll
Running under executable  C:\temp\bar.exe
— A detailed error log follows.
=== Pre-bind state information ===
LOG: User = Bart-PC\Bart
LOG: DisplayName = foo, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null
(Fully-specified)
LOG: Appbase = file:///C:/temp/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = bar.exe
Calling assembly : bar, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null.
===
LOG: This bind starts in default load context.
LOG: Private path hint found in configuration file: oops.
LOG: Using application configuration file: C:\temp\bar.exe.config
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/foo.DLL.
LOG: Attempting download of new URL file:///C:/temp/foo/foo.DLL.
LOG: Attempting download of new URL file:///C:/temp/oops/foo.DLL.

LOG: Assembly download was successful. Attempting setup of file: C:\temp\oops\foo.dll
LOG: Entering run-from-source setup phase.
LOG: Assembly Name is: foo, Version=0.0.0.0, Culture=neutral, PublicKeyToken=null
LOG: Binding succeeds. Returns assembly from C:\temp\oops\foo.dll.
LOG: Assembly is loaded in default load context.

As you can see, the oops path is being probed and the assembly is found thanks to our "private path hint" in the configuration file.

Conclusion

Once the FileNotFoundExceptin might have been your worst nightmare (actually MissingMethodException should deserve that spot) but when things get bad, Fusion comes to the rescue. Happy probing!

Enable Fusion Assembly Binding Logging

The WRN: Assembly binding logging is turned off message is annoying but assembly binding logging can be extremely helpful when you need to know how .NET is (or isn’t) locating the assemblies you’ve referenced. The message is annoying because, if you’re like me, you never have logging enabled and the registry key cited is a bit unusual:

To enable assembly bind failure logging, set the registry value [HKLM\Software\Microsoft\Fusion!EnableLog] (DWORD) to 1.

What does the exclamation mark mean? Presumably EnableLog is a DWORD in the Fusion key but it’s all a bit unclear for my liking. Once you’ve set this DWORD, you need to figure out what to do next and for many people that will likely involve firing up the Fusion Log Viewerfuslogvw.exe or the Windows/.NET SDK. But then what?

Gary Kindel was kind enough to post the following details in response to a related Stack Overflow question:

Add the following values to HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Fusion
DWORD ForceLog set value to 1
DWORD LogFailures set value to 1
DWORD LogResourceBinds set value to 1
String LogPath set value to folder for logs ie) C:\FusionLog\

Make sure you include the backslash after the folder name. I also found an IISRESET was necessary in a web context.

Since I wanted to enable this logging in an environment without Visual Studio or the Windows SDK installed, the above option was clean and lightweight. Log files were dumped to the expected location in .html format and it was then a case of locating the assembly I was interested in… and, oh yeah, fixing the problem 😉 The issue was also detailed in the ASP.NET error message returned by IIS.

Advanced geeks: because Fusion logging supposedly affects performance, you might want to create a reg file/batch script to toggle logging on and off. Here’s a starting point—put this into a file called EnableFusionLogging.reg and double-click to run it:

Windows Registry Editor Version 5.00

[HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Fusion]
"ForceLog"=dword:00000001
"LogFailures"=dword:00000001
"LogResourceBinds"=dword:00000001
"LogPath"="C:\\Temp\\FusionLog\\"

I actually call this from a batch script which also resets IIS and I have a mirror reg file that disables logging.

http://community.bartdesmet.net/blogs/bart/archive/2006/10/23/Assembly-probing_2C00_-Fusion-and-fuslogvw-in-5-minutes.aspx

http://blog.mediawhole.com/2010/08/enable-fusion-assembly-binding-logging.html

http://stackoverflow.com/questions/255669/how-to-enable-assembly-bind-failure-logging-fusion-in-net/1527249#1527249

Anuncios

Responder

Introduce tus datos o haz clic en un icono para iniciar sesión:

Logo de WordPress.com

Estás comentando usando tu cuenta de WordPress.com. Cerrar sesión / Cambiar )

Imagen de Twitter

Estás comentando usando tu cuenta de Twitter. Cerrar sesión / Cambiar )

Foto de Facebook

Estás comentando usando tu cuenta de Facebook. Cerrar sesión / Cambiar )

Google+ photo

Estás comentando usando tu cuenta de Google+. Cerrar sesión / Cambiar )

Conectando a %s

 
A %d blogueros les gusta esto: