One of the developers who uses the .NET/COM interop DLL that I wrote recently informed me that when they used it in a certain way, they would get a fatal System.InvalidProgramException. Nasty. So I set about seeing how I could find out exactly why this was happening: here are the gory details…
To spoil the ending somewhat, we already knew the precise situation that was causing the problem. This is different to the average issue, where most of the time’s spent in isolating the conditions that cause it. In this case we had an excellent positive and negative repro case.
The users were attempting to use the legacy .local approach to changing DLL probing. This was originally implemented around the time of Windows 2000, before the current side-by-side system existed, and basically short-circuited the normal DLL search order to inject the current directory as the first potential location. See the DLL redirection MSDN page for more information.
There was already a version of the assembly in question installed in the GAC, they just wanted to use the .local file to override it. The trouble was, with certain builds of the DLL (we’ll call it XYZ.dll) in the directory along with the redirection file (appname.exe.local), an fatal InvalidProgramException would be generated by the .NET execution engine. With other builds of the same DLL it worked. Mysterious.
So the first thing to do was to try and find out exactly where the exception was occurring. I ramped up WinDbg, and took a look at what exceptions were being thrown:
(42c.1e90): CLR notification exception - code e0444143 (first chance)
(42c.1e90): Unknown exception - code 02345678 (first chance)
(42c.1e90): C++ EH exception - code e06d7363 (first chance)
(42c.1e90): C++ EH exception - code e06d7363 (first chance)
(42c.1e90): C++ EH exception - code e06d7363 (first chance)
(42c.1e90): CLR exception - code e0434f4d (first chance)
The last one generated a second chance exception and the exit. I changed the exception filter set to stop on .NET notifications – which are generated when assemblies are loaded – and for C++ exceptions:
0:000> sxe clrn
0:000> sxe eh
After restarting and running on from the CLR notification (generated whenever an assembly is loaded) I got a stack trace on the C++ exception that was being generated within the CLR:
0:000> kP
ChildEBP RetAddr
0012eea4 78158e89 KERNEL32!RaiseException+0x53
0012eedc 79fce58e MSVCR80!_CxxThrowException+0x46
0012ef0c 7a015309 mscorwks!RealCOMPlusThrow+0xd8
0012f2ac 79f0e795 mscorwks!UnsafeJitFunction+0x365
0012f350 79e87f52 mscorwks!MethodDesc::MakeJitWorker+0x1c1
0012f3a8 79e8809e mscorwks!MethodDesc::DoPrestub+0x486
0012f3f8 00341f3e mscorwks!PreStubWorker+0xeb
Hmmmm, interesting, so it looks like the JIT compiler is failing. I also noticed that there was a strange exception that I didn’t recognise:
(42c.1e90): Unknown exception - code 02345678 (first chance)
You’ve got to love those “made up” numbers. I added an exception filter for it and restarted again (good job this failure was quick to manifest).
Now I got an even more precise fault location:
0:000> kP
ChildEBP RetAddr
0012ec44 790af56c KERNEL32!RaiseException+0x53
0012ec60 7909deea mscorjit!getJit+0x38
0012ec7c 79066362 mscorjit!Compiler::fgFindJumpTargets+0x33d
0012ece0 790614c6 mscorjit!Compiler::fgFindBasicBlocks+0x4d
0012ed20 79061236 mscorjit!Compiler::compCompile+0x2bf
0012edb4 7906118c mscorjit!jitNativeCode+0xb8
0012edec 79f0f9cf mscorjit!CILJit::compileMethod+0x3d
0012ee58 79f0f945 mscorwks!invokeCompileMethodHelper+0x72
0012ee9c 79f0f8da mscorwks!invokeCompileMethod+0x31
0012eef4 79f0ea33 mscorwks!CallCompileMethodWithSEHWrapper+0x84
0012f2ac 79f0e795 mscorwks!UnsafeJitFunction+0x230
0012f350 79e87f52 mscorwks!MethodDesc::MakeJitWorker+0x1c1
0012f3a8 79e8809e mscorwks!MethodDesc::DoPrestub+0x486
0012f3f8 00341f3e mscorwks!PreStubWorker+0xeb
So now its looking like something’s going wrong deep down in the JITter. After stepping through the disassembly for a while I decided to have a look at precisely what method was being compiled at this point. You can use the DumpMD command from the sos extension to examine the method, which is the first parameter to UnsafeJitFunction (you can see parameters in the stack trace by using kb):
0:000> !DumpMD 0161ad08
Method Name: XXX()
Class: 01670a40
MethodTable: 0161ad18
mdToken: 0601626b
Module: 00d3323c
IsJitted: no
m_CodeOrIL: ffffffff
Now this is suspicious; the method as listed (XXX – name changed to protect the innocent) isn’t what we were expecting. In fact, it’s completely different. Let’s see what IL is being JITted:
0:000> !DumpIL 161ad08
error decoding IL
OK, so this is completely broken metadata.
Now, given that we were using the .local, we would have expected to see the DLL being loaded from the same directory as the application, so lets take a look and see what we’ve got loaded:
0:000> !DumpDomain
--------------------------------------
System Domain: 7a3bc8b8
...snip...
Assembly: 001abe28 [C:\WINNT\assembly\GAC_MSIL\XYZ.DLL]
ClassLoader: 001aa0b0
SecurityDescriptor: 001aa018
Module Name
00d3323c C:\WINNT\assembly\GAC_MSIL\XYZ.DLL
So this looks like the culprit; we’re still loading the version from the GAC, even though there’s a .local file present. Just to verify this I set a breakpoint on CreateFileW to show me which DLLs were being loaded and by what:
0:000> bu KERNEL32!CreateFileW "dpu (@esp+4) L1"
This tells the debugger to display the unicode string that is the first parameter to CreateFileW whenever it’s hit.
There are obviously lots of DLLs loaded, even in this simple case, but eventually it led me to the point where the GAC version was being loaded:
0012cf44 001ac5a0 "C:\WINNT\assembly\GAC_MSIL\XYZ.dll"
eax=00000000 ebx=00000001 ecx=79e7f683 edx=7c90eb94 esi=001ac4e0 edi=7c80ac0f
eip=7c810760 esp=0012cf40 ebp=0012cf64 iopl=0 nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000202
KERNEL32!CreateFileW:
7c810760 8bff mov edi,edi
0:000> kp L30
ChildEBP RetAddr
0012cf3c 79e90f12 KERNEL32!CreateFileW
0012cf64 79f29306 mscorwks!WszCreateFile+0x72
0012cfac 79ed27ac mscorwks!PEImage::GetFileHandle+0x60
0012cfdc 79e981ae mscorwks!PEImage::GetLayoutInternal+0xcf
0012d020 79e98e69 mscorwks!PEImage::GetLayout+0x8a
0012d0bc 79e98934 mscorwks!RuntimeOpenImageInternal+0x103
0012d104 79e988a9 mscorwks!GetAssemblyMDInternalImportEx+0x9d
0012d11c 79ec314d mscorwks!CreateMetaDataImport+0x16
0012d13c 79ec30ee mscorwks!CAssemblyManifestImport::Init+0x35
0012d164 79ed39ca mscorwks!CreateAssemblyManifestImport+0x53
0012d180 79ed3943 mscorwks!CreateAssemblyFromManifestFile+0x48
0012d3e8 79ed380f mscorwks!CheckExistsInGAC+0x179
0012d418 79ed320a mscorwks!CreateAssemblyFromCacheLookup+0x9b
...snip...
So then I waited until the exception was fired, and used !dlls to show me what other DLLs were loaded:
0:000> !dlls
...
0x00243a68: C:\Temp\interopx\XYZ.dll
Base 0x036a0000 EntryPoint 0x00000000 Size 0x0095c000
Flags 0x90404000 LoadCount 0x00000001 TlsIndex 0x00000000
LDRP_ENTRY_PROCESSED
LDRP_COR_IMAGE
...
Ouch. We’ve loaded some metadata from the c:\winnt\assembly\GAC_MSIL\XYZ.dll version, and then we’ve actually loaded the c:\temp\interopx\XYZ.dll module. It turned out that in some cases the metadata matched, and we got away with it, and at other times (for different builds) it didn’t and we hit the InvalidProgramException.
So, the moral of the story is, don’t mix .local and the .NET assembly loader. And if you do, prepare to break out your WinDbg skills.
Ever been in that situation where you (or someone else) finds that Visual Studio just won’t set a breakpoint in some source code that you’re sure should be being used? You’ll see the hollow breakpoint icon and something like ‘The breakpoint will not currently be hit. No symbols have been loaded for this document’.
