Yet Another Debugging Tale – Visual Studio Disappearing

Call me a nerd (that’s obvious!), but I find a good debugging tale like something of a geek murder thriller. Every issue has its own little debugging quirks. This blog post, and some of my previous ones, are posted to be both entertaining as well as educational. I don’t want to bore you to death with cdb or WinDbg documentation, but you might find some of the approaches useful in the future.

The Issue

This morning ScottGu announced NuPack, a package management solution for .NET.

Eager to try it out, I opened an existing solution, expanded a web application project, right clicked on the References node and chose Add Package Reference.

The dialog popped up for a second or so and then my entire VS shell just disappeared without a trace. No error. No crash dialogs. Nothing.

This happened reliably every time.

Note: This issue is now fixed in the latest source.

My Debugging Steps

I opened a fresh instance of VS, attached WinDbg, opened the solution in question, and expanded the project nodes.

Before opening the context menu, I set a pretty wide exception breakpoint:

 0:051> !soe -derived -create System.Exception 1 Breakpoint set 

Then resumed execution:

 0:051> g 

Next, I right clicked on the References node and clicked Add Packaged Reference.

Bam! Exception:

(1ee4.1144): Access violation - code c0000005 (first chance)
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
eax=00000000 ebx=00000000 ecx=00000000 edx=00000000 esi=2b542f64 edi=2b5fb018
eip=03458ddf esp=00457b30 ebp=00457b38 iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00010246
03458ddf 8b721c          mov     esi,dword ptr [edx+1Ch] ds:002b:0000001c=????????

Where is it?

0:000> !clrstack
OS Thread Id: 0x1144 (0)
Child SP IP       Call Site
00457b30 03458ddf NuPack.Dialog.Providers.OnlinePackagesProvider.IsInstalled(System.String)*** ERROR: Module load completed but symbols could not be loaded for NuPack.Dialog.dll

00457b40 03458dae NuPack.Dialog.Providers.OnlinePackagesItem.get_IsInstalled()
00458094 5ad921db [DebuggerU2MCatchHandlerFrame: 00458094] 
00458060 5ad921db [CustomGCFrame: 00458060] 
00458034 5ad921db [GCFrame: 00458034] 
00458018 5ad921db [GCFrame: 00458018] 
0045823c 5ad921db [HelperMethodFrame_PROTECTOBJ: 0045823c] System.RuntimeMethodHandle._InvokeMethodFast(System.IRuntimeMethodInfo, System.Object, System.Object[], System.SignatureStruct ByRef, System.Reflection.MethodAttributes, System.RuntimeType)
004582b8 55b1d689 System.RuntimeMethodHandle.InvokeMethodFast(System.IRuntimeMethodInfo, System.Object, System.Object[], System.Signature, System.Reflection.MethodAttributes, System.RuntimeType)*** WARNING: Unable to verify checksum for C:\Windows\assembly\NativeImages_v4.0.30319_32\mscorlib\4ff1f12a08d455f195ba996fe77497c6\mscorlib.ni.dll

0045830c 55b1d3d0 System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo, Boolean)
00458348 55b1bfed System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
0045836c 55af63f8 System.Reflection.RuntimePropertyInfo.GetValue(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
00458390 55af63ac System.Reflection.RuntimePropertyInfo.GetValue(System.Object, System.Object[])
0045839c 52076f58 MS.Internal.Data.PropertyPathWorker.GetValue(System.Object, Int32)

[...]

At this stage there’s no managed exception yet, so I stepped out a few times until I got one:

0:000> gu
(1ee4.1144): CLR exception - code e0434352 (first chance)
'System.Exception hit'
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
eax=00457e40 ebx=00000005 ecx=00000005 edx=00000000 esi=00457eec edi=0027fbe0
eip=75d9b727 esp=00457e40 ebp=00457e90 iopl=0         nv up ei pl nz ac po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000212
KERNELBASE!RaiseException+0x58:
75d9b727 c9              leave
0:000> !pe
Exception object: 2b613d1c
Exception type:   System.Reflection.TargetInvocationException
Message:          Exception has been thrown by the target of an invocation.
InnerException:   System.NullReferenceException, Use !PrintException 2b6125a0 to see more.
StackTrace (generated):
<none>
StackTraceString: <none>
HResult: 80131604
0:000> !pe 2b6125a0
Exception object: 2b6125a0
Exception type:   System.NullReferenceException
Message:          Object reference not set to an instance of an object.
InnerException:   <none>
StackTrace (generated):
    SP       IP       Function
    00457B20 03458DDF NuPack_Dialog_1b750000!NuPack.Dialog.Providers.OnlinePackagesProvider.IsInstalled(System.String)+0xf
    00457B30 03458DAE NuPack_Dialog_1b750000!NuPack.Dialog.Providers.OnlinePackagesItem.get_IsInstalled()+0x1e

StackTraceString: <none>
HResult: 80004003

A quick trip to Reflector shows this to be the culprit (NuPack source was only published after this debugging exercise):

public bool IsInstalled(string id)
{
    return (this.ProjectManager.LocalRepository.FindPackage(id) != null);
}

Either get_ProjectManager or get_LocalRepository is returning null.

I let the app crash, then setup the scenario again.

This time I caught a tighter exception:

0:061> !soe -create2 System.NullReferenceException
Breakpoint set
0:061> g

As expected, we got a hit in the same place:

0:000> !clrstack
OS Thread Id: 0x1634 (0)
Child SP IP       Call Site
00367ab0 027bd85f NuPack.Dialog.Providers.OnlinePackagesProvider.IsInstalled(System.String)*** ERROR: Module load completed but symbols could not be loaded for NuPack.Dialog.dll

00367ac0 027bd82e NuPack.Dialog.Providers.OnlinePackagesItem.get_IsInstalled()
00368014 5ad921db [DebuggerU2MCatchHandlerFrame: 00368014] 
00367fe0 5ad921db [CustomGCFrame: 00367fe0] 
00367fb4 5ad921db [GCFrame: 00367fb4] 
00367f98 5ad921db [GCFrame: 00367f98] 
003681bc 5ad921db [HelperMethodFrame_PROTECTOBJ: 003681bc] System.RuntimeMethodHandle._InvokeMethodFast(System.IRuntimeMethodInfo, System.Object, System.Object[], System.SignatureStruct ByRef, System.Reflection.MethodAttributes, System.RuntimeType)
00368238 55b1d689 System.RuntimeMethodHandle.InvokeMethodFast(System.IRuntimeMethodInfo, System.Object, System.Object[], System.Signature, System.Reflection.MethodAttributes, System.RuntimeType)*** WARNING: Unable to verify checksum for C:\Windows\assembly\NativeImages_v4.0.30319_32\mscorlib\4ff1f12a08d455f195ba996fe77497c6\mscorlib.ni.dll

0036828c 55b1d3d0 System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo, Boolean)
003682c8 55b1bfed System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
003682ec 55af63f8 System.Reflection.RuntimePropertyInfo.GetValue(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
00368310 55af63ac System.Reflection.RuntimePropertyInfo.GetValue(System.Object, System.Object[])
0036831c 52416f58 MS.Internal.Data.PropertyPathWorker.GetValue(System.Object, Int32)

[...]

I grabbed the native disassembly:

0:000> !u 027bd85f
Normal JIT generated code
NuPack.Dialog.Providers.OnlinePackagesProvider.IsInstalled(System.String)
Begin 027bd850, size 51
027bd850 55              push    ebp
027bd851 8bec            mov     ebp,esp
027bd853 57              push    edi
027bd854 56              push    esi
027bd855 8bfa            mov     edi,edx
027bd857 ff1570007e02    call    dword ptr ds:[27E0070h] (NuPack.Dialog.Providers.OnlinePackagesProvider.get_ProjectManager(), mdToken: 06000048)
027bd85d 8bd0            mov     edx,eax
>>> 027bd85f 8b721c          mov     esi,dword ptr [edx+1Ch]
027bd862 33c9            xor     ecx,ecx
027bd864 33d2            xor     edx,edx
027bd866 e8057b2e53      call    mscorlib_ni+0x245370 (55aa5370) (System.Version.op_Equality(System.Version, System.Version), mdToken: 06001487)
027bd86b 85c0            test    eax,eax
027bd86d 750e            jne     027bd87d
027bd86f 6a00            push    0
027bd871 8bd7            mov     edx,edi
027bd873 8bce            mov     ecx,esi
027bd875 ff153818f901    call    dword ptr ds:[1F91838h]
027bd87b eb18            jmp     027bd895
027bd87d 8bd7            mov     edx,edi
027bd87f 8bce            mov     ecx,esi
027bd881 ff15a82a7f02    call    dword ptr ds:[27F2AA8h] (NuPack.PackageRepositoryExtensions.FindPackagesById(NuPack.IPackageRepository, System.String), mdToken: 06000285)
027bd887 6a00            push    0
027bd889 6a00            push    0
027bd88b 8bc8            mov     ecx,eax
027bd88d 33d2            xor     edx,edx
027bd88f ff15142b7f02    call    dword ptr ds:[27F2B14h] (NuPack.PackageExtensions.FindByVersion(System.Linq.IQueryable`1<NuPack.IPackage>, System.Version, System.Version, System.Version), mdToken: 060001c5)
027bd895 85c0            test    eax,eax
027bd897 0f95c0          setne   al
027bd89a 0fb6c0          movzx   eax,al
027bd89d 5e              pop     esi
027bd89e 5f              pop     edi
027bd89f 5d              pop     ebp
027bd8a0 c3              ret

From this we can note that the crash is after the call to get_ProjectManager but before a call to System.Version.op_Equality.

Checking the eax register shows that the call to get_ProjectManager returned null:

0:000> r
eax=00000000 ebx=00465938 ecx=0046c824 edx=00000004 esi=00000043 edi=00004000
eip=5ad91984 esp=00465868 ebp=00465868 iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
clr!StressLog::StressLogOn+0xa:
5ad91984 854508          test    dword ptr [ebp+8],eax ss:002b:00465870=00004000

How could this occur?

protected ProjectManager ProjectManager
{
    get
    {
        return this.PackageManager.GetProjectManager((Project) this.Project);
    }
}

public ProjectManager GetProjectManager(Project project)
{
    ProjectManager manager;
    this.EnsureProjectManagers();
    this._projectManagers.TryGetValue(project, out manager);
    return manager;
}

From Reflector, we can see that get_ProjectManager calls into GetProjectManager.

This latter methods ‘ensures’ that a dictionary is initialized, then tries to return a value from it.

If the EnsureProjectManagers() method logic is wrong at all, and TryGetValue returns null, the application crashes. If it is always expected that this method will return a value, TryGetValue(Project, out ProjectManager) should be replaced with a standard dictionary lookup. If it’s valid for this method to return null, then NuPack.Dialog.Providers.OnlinePackagesProvider.get_ProjectManager or NuPack.Dialog.Providers.OnlinePackagesProvider.IsInstalled(string) need to be updated to handle null values.

Let’s work out why it returned null. First up, lets find all PackageManager instances on the heap so we can interrogate them:

0:000> !dumpheap -type NuPack.ProjectManager
Address       MT     Size
2bceed0c 21187e4c       52     
2bcf7450 21189858       60     
total 0 objects
Statistics:
      MT    Count    TotalSize Class Name
21187e4c        1           52 System.Collections.Generic.Dictionary`2[[EnvDTE.Project, NuPack.VisualStudio],[NuPack.ProjectManager, NuPack.Core]]
21189858        1           60 System.Collections.Generic.Dictionary`2+Entry[[EnvDTE.Project, NuPack.VisualStudio],[NuPack.ProjectManager, NuPack.Core]][]
Total 2 objects

Out of these two, the first one is the interesting one:

0:000> !do 2bceed0c
Name:        System.Collections.Generic.Dictionary`2[[EnvDTE.Project, NuPack.VisualStudio],[NuPack.ProjectManager, NuPack.Core]]
MethodTable: 21187e4c
EEClass:     558b99ac
Size:        52(0x34) bytes
File:        C:\Windows\Microsoft.Net\assembly\GAC_32\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
55b82938  4000bd3        4       System.Int32[]  0 instance 2bcf7438 buckets
56320924  4000bd4        8 ...non, mscorlib]][]  0 instance 2bcf7450 entries
55b82978  4000bd5       20         System.Int32  1 instance        3 count
55b82978  4000bd6       24         System.Int32  1 instance        3 version
55b82978  4000bd7       28         System.Int32  1 instance       -1 freeList
55b82978  4000bd8       2c         System.Int32  1 instance        0 freeCount
55b82fd8  4000bd9        c ...Canon, mscorlib]]  0 instance 2bceed70 comparer
55b7568c  4000bda       10 ...Canon, mscorlib]]  0 instance 00000000 keys
55b7b730  4000bdb       14 ...Canon, mscorlib]]  0 instance 00000000 values
55b7f5e8  4000bdc       18        System.Object  0 instance 00000000 _syncRoot
55b7b794  4000bdd       1c ...SerializationInfo  0 instance 00000000 m_siInfo

The count is correct. (My solution has three projects.)

This indicates that the dictionary context is correct, but that we’re looking for the wrong key.

This is where the lookup key comes from:

protected ProjectManager ProjectManager
{
    get
    {
        return this.PackageManager.GetProjectManager((Project) this.Project);
    }
}

protected Project Project
{
    get
    {
        return Utilities.GetActiveProject(this.DTE);
    }
}

public static Project GetActiveProject(_DTE dte)
{
    Project project = null;
    if (dte != null)
    {
        object activeSolutionProjects = dte.ActiveSolutionProjects;
        if (((activeSolutionProjects != null) && (activeSolutionProjects is Array)) && (((Array) activeSolutionProjects).Length > 0))
        {
            object obj3 = ((Array) activeSolutionProjects).GetValue(0);
            if ((obj3 != null) && (obj3 is Project))
            {
                project = (Project) obj3;
            }
        }
    }
    return project;
}

In the last method, there are a whole host of scenarios that would cause it to return null. This will then cascade through GetProjectManager(Project) and get_ProjectManager before resulting in the NullReference exception we saw in IsInstalled(string). Either GetActiveProject(_DTE) should be updated to fail fast when the active project cannot be determined, or IsInstalled(string) needs to be updated to handle this scenario.

Which scenario caused GetActiveProject(_DTE) to return null for me?

Interrogating the _DTE instance was beyond me because it’s a COM object. By this point I had a pretty good idea though so trial and error got me the rest of the way.

My Diagnosis

The traditional Solution Explorer tool window needs to be opened at least once between opening a solution and trying to add a package reference. If you’re exclusively using the Solution Navigator tool window from the power tools, your VS will disappear as soon as you try to add the package reference.

My Repro Steps

1. Open Visual Studio
2. Close the Solution Explorer tool window
3. Open the Solution Navigator tool window (the one from the power tools)
4. Open your .sln
5. In the Solution Navigator, expand a project
6. Right click the ‘References’ node
7. Click ‘Add Package Reference’
8. Boom!

I hope you found this story interesting for the mystery factor, as well as showing a few debugging techniques that I use. 🙂