Assemblies Failing to load in shadow copied AppDomain

Question

I write the xunit.net test runner for ReSharper, and I've got an issue in the 8.0 release - I'm seeing assemblies failing to load in a shadow copied AppDomain. The same code and test project work fine in the 7.1 release. I don't understand why, though.

When running tests, ReSharper spawns an executable that loads my plugin. I use xunit.net's API to create an AppDomain that has shadow copy enabled. The test project assembly is copied into the shadow copy cache, and starts to load. It copies a dependency into the cache, and loads it - an older version of FakeItEasy, which uses Assembly.LoadFile to load all of the assemblies in the current directory, which is the bin\Debug folder of the test project. So, FakeItEasy loads these assemblies into the Neither load context. Since it's using LoadFile, it bypasses the shadow copy cache, and the files are loaded direct from the bin\Debug folder.

After this, the dependencies of the test project fail to load, resulting in a FileNotFoundException. Fusion binding logs show that it tries to load them, but they don't get copied in the shadow copy cache, and they fail to load. I can't see why. Here's the binding failure:

LOG: This bind starts in default load context.
LOG: No application configuration file found.
LOG: Using host configuration file: 
LOG: Using machine configuration file from     C:\Windows\Microsoft.NET\Framework64\v4.0.30319\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/todonancy/TodoNancyTests/bin/Debug/Nancy.Testing.DLL.
LOG: Assembly download was successful. Attempting setup of file: C:\temp\todonancy\TodoNancyTests\bin\Debug\Nancy.Testing.dll
LOG: Entering download cache setup phase.
LOG: Assembly Name is: Nancy.Testing, Version=0.17.1.0, Culture=neutral, PublicKeyToken=null
ERR: Setup failed with hr = 0x80070003.
ERR: Failed to complete setup of assembly (hr = 0x80070003). Probing terminated.

If I disable shadow copy cache, or use a newer version of FakeItEasy that doesn't use LoadFile, it all works. However, I can't blame the older vesion of FakeItEasy - I have users seeing the same errors with other projects and assemblies, all solved by disabling shadow copy cache.

Also, this scenario does work with ReSharper 7.1 - same plugin code and same test project. The only difference is the host application, but I can't see it doing anything different - there are no other assembly resolve event handlers subscribed, for example. The only real difference is that the 7.1 host uses remoting to talk to the Visual Studio application, and the 8.0 uses simple TCP sockets.

Does anyone have any idea why this is failing in the 8.0 version, and yet running with 7.1?

EDIT (07/08/2013):

I've managed to make it fail with a simple test:

[Fact]
public void Thing()
{
  Assert.NotNull(Nancy.Bootstrapper.AppDomainAssemblyTypeScanner.Assemblies);
}

Using a copy of the Nancy class added straight into the project (with the referenced ScanMode and AssemblyExtensions classes). The only other content in the project is a reference to xunit.dll and xunit.extensions.dll.

It doesn't fail every time, it's frustratingly intermittent, but I can get it to throw a FileNotFoundException in this call to Assembly.ReflectionOnlyLoadFrom while trying to load the test assembly from the bin\Debug folder.

Here's the fusion log from the exception:

Assembly manager loaded from:  C:\Windows\Microsoft.NET\Framework64\v4.0.30319\clr.dll
Running under executable  C:\Program Files (x86)\JetBrains\ReSharper\v8.0\Bin\JetBrains.ReSharper.TaskRunner.CLR4.MSIL.exe
--- A detailed error log follows. 

=== Pre-bind state information ===
LOG: Where-ref bind. Location = C:\Users\Matt\Code\scratch\WeirdXunitFailures\WeirdXunitFailures\bin\Debug\WeirdXunitFailures.dll
LOG: Appbase = file:///C:/Users/Matt/Code/scratch/WeirdXunitFailures/WeirdXunitFailures/bin/Debug
LOG: Initial PrivatePath = NULL
Calling assembly : (Unknown).
===
LOG: This is an inspection only bind.
LOG: No application configuration file found.
LOG: Using host configuration file: 
LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework64\v4.0.30319\config\machine.config.
LOG: Attempting download of new URL file:///C:/Users/Matt/Code/scratch/WeirdXunitFailures/WeirdXunitFailures/bin/Debug/WeirdXunitFailures.dll.
ERR: Failed to complete setup of assembly (hr = 0x80070003). Probing terminated.

Unfortunately, this tells me nothing - the file:// url is valid, and the shadow copy cache contains xunit.dll and WeirdXunitFailures.DLL (the test project). Also, the Modules window in the debugger is showing me that WeitdXunitFailures.dll is already loaded, from the shadow copy cache location.

And again, the really weird thing is that the 7.1 runner works just fine.

EDIT:

In fact, I can get it to fail simply by calling:

[Fact]
public void Thing()
{
  Assembly.ReflectionOnlyLoadFrom(@"C:\Users\Matt\Code\scratch\WeirdXunitFailures\WeirdXunitFailures\bin\Debug\xunit.dll");
  Assembly.ReflectionOnlyLoadFrom(@"C:\Users\Matt\Code\scratch\WeirdXunitFailures\WeirdXunitFailures\bin\Debug\xunit.extensions.dll");
  Assembly.ReflectionOnlyLoadFrom(@"C:\Users\Matt\Code\scratch\WeirdXunitFailures\WeirdXunitFailures\bin\Debug\WeirdXunitFailures.dll");
}

These are the project dll and the two xunit dlls. It's still very intermittent, but seems to be most easily reproduced after a complete rebuild, although it does still occur after several successful runs (so it's not the rebuild that's at fault)

Answer 1

Phew. The problem was (naturally) a subtle change in behaviour in ReSharper 8.

The test runner process API has a method to tell the main ReSharper process (i.e. devenv.exe) the location of the temp folder used for the test run - the shadow copy cache. This is because the test runner process usually can't delete the cache folder because it's still in use. ReSharper will then make several attempts to delete the folder for you, allowing time for the process to die gracefully.

ReSharper 7.1 would delete this folder at the end of a test run, or if the run was aborted.

ReSharper 8 deletes the folder as soon as you call you the method. The nunit test runner tells ReSharper about it at the end of the test run. I was telling it about it at the start. And so ReSharper would happily come along, while my tests were running, and delete whatever it could from the shadow copy cache, making it look like the shadow copy cache was properly broken.

I think I'll be filing a bug :)