{"id":104684,"date":"2021-01-08T07:00:00","date_gmt":"2021-01-08T15:00:00","guid":{"rendered":"https:\/\/devblogs.microsoft.com\/oldnewthing\/?p=104684"},"modified":"2021-01-08T07:08:36","modified_gmt":"2021-01-08T15:08:36","slug":"20210108-00","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20210108-00\/?p=104684\/","title":{"rendered":"The case of the crash during the release of an object from an unloaded DLL during apartment rundown"},"content":{"rendered":"

A Windows component was experiencing a crash in its service. Here’s the stack trace:<\/p>\n

Call Site\r\nntdll!RtlUnhandledExceptionFilter2+0x364\r\nKERNELBASE!UnhandledExceptionFilter+0x1f1\r\nntdll!RtlpThreadExceptionFilter+0x65\r\nntdll!RtlUserThreadStart$filt$0+0x76\r\nntdll!__C_specific_handler+0x96\r\nntdll!RtlpExecuteHandlerForException+0xf\r\nntdll!RtlDispatchException+0x21c\r\nntdll!KiUserExceptionDispatch+0x2e\r\ncombase!CStdMarshal::DisconnectSrvIPIDs::__l35::<lambda_03ceb3c306c371a8ea5da27fc98e7b7c>::operator()+0x11\r\ncombase!ObjectMethodExceptionHandlingAction<<lambda_03ceb3c306c371a8ea5da27fc98e7b7c> >+0x2e\r\ncombase!CStdMarshal::DisconnectSrvIPIDs+0x3fb\r\ncombase!CStdMarshal::DisconnectWorker_ReleasesLock+0x757\r\ncombase!CStdMarshal::DisconnectSwitch_ReleasesLock+0x1c\r\ncombase!CStdMarshal::DisconnectAndReleaseWorker_ReleasesLock+0x32\r\ncombase!COIDTable::ThreadCleanup+0x130\r\ncombase!FinishShutdown::__l2::<lambda_eb459d6b43445c5cc6a7489c5b769eeb>::operator()+0x5\r\ncombase!ObjectMethodExceptionHandlingAction<<lambda_eb459d6b43445c5cc6a7489c5b769eeb> >+0x9\r\ncombase!FinishShutdown+0x78\r\ncombase!NAUninitialize+0x5e\r\ncombase!ApartmentUninitialize+0x177\r\ncombase!wCoUninitialize+0x1c4\r\ncombase!CoUninitialize+0xeb\r\nsvchost!SvcHostMain+0x328\r\nsvchost!wmain+0x9\r\nsvchost!__wmainCRTStartup+0x74\r\nkernel32!BaseThreadInitThunk+0x14\r\nntdll!RtlUserThreadStart+0x2b\r\n<\/pre>\n
First let’s understand what the stack is telling us.<\/p>\n
Reading from the bottom, we see that the service host calls CoUninitialize<\/code> to uninitialize COM, presumably because the service is shutting down. This goes into combase<\/code> and it’s doing a bunch of cleanup work. Eventually, it gets into Disconnect\u00adSrv\u00adIPIDs<\/code>.<\/p>\n
When you go digging into COM, you’ll run into a bunch of weird acronymy IDs. Here are the ones you’re most likely to bump into:<\/p>\n\n\n\n\n\n\n\n
Term<\/th>\nMeaning<\/th>\n<\/tr>\n
MID<\/td>\nMachine identifier<\/td>\n<\/tr>\n
OXID<\/td>\nObject exporter identifier<\/td>\n<\/tr>\n
OID<\/td>\nObject identifier<\/td>\n<\/tr>\n
IPID<\/td>\nInterface pointer identifier<\/td>\n<\/tr>\n<\/tbody>\n<\/table>\n
Object exporter<\/i> is a fancy name for COM apartment<\/i>.<\/p>\n
The tuple of (MID, OXID, OID, IPID) uniquely identify an instance of an interface anywhere in the known COM universe.<\/p>\n
When an apartment is shut down, one of the things that COM needs to do is run down<\/i> objects. Running down<\/i> is just a fancy way of saying “shut down in an organized way”. In this case, it means that any outstanding clients are disconnected so that they can’t call back into the object any more. This in turn causes the underlying object to be released, at which point is is most likely going to destroy itself.<\/p>\n
We crashed during this disconnection process. Since we are in Rtl\u00adUnhandled\u00adException\u00adFilter2<\/code>, this suggests that we are in an exception filter, and the first parameter to the exception filter is a pointer to an EXCEPTION_POINTERS<\/code> structure, which is just  a pair of pointers<\/a>, one to the exception record and one to the context.<\/p>\n
We are interested in the context, because that lets us see the underlying exception. How can we fish it out?<\/p>\n
This is a 64-bit process, and the EXCEPTION_POINTERS<\/code> pointer is the first parameter, so it came in the rcx<\/code> register. Let’s see if we can see what the function did with that register:<\/p>\n
ntdll!RtlUnhandledExceptionFilter2:\r\n    mov     qword ptr [rsp+10h],rdx\r\n    mov     qword ptr [rsp+8],rcx < Went onto the stack\r\n    push    rbx\r\n    push    rsi\r\n    push    rdi\r\n    push    r12\r\n    push    r13\r\n    push    r14\r\n    push    r15\r\n    sub     rsp,40h\r\n    mov     r13,rdx\r\n    mov     r14,rcx < Went into the r14 register\r\n    mov     rax,qword ptr gs:[60h]\r\n    mov     r15,qword ptr [rax+20h]\r\n    xor     esi,esi\r\n    test    r15,r15\r\n    je      ntdll!RtlUnhandledExceptionFilter2+0x39\r\n<\/pre>\n
The value in the rcx<\/code> register got saved in two places: It went into the home space on the stack, and it was also stashed into the r14<\/code> register.<\/p>\n
Let’s see what’s there:<\/p>\n
0:000> dps @rsp+40+38+8 L1\r\n000000a5`a7c8e470  000000a5`a7c8df40 \r\n0:000> dps @r14 L2\r\n000000a5`a7c8df40  000000a5`a7c8ebb0\r\n000000a5`a7c8df48  000000a5`a7c8e6c0\r\n<\/pre>\n
Reading the disassembly, we see that the stack pointer is adjusted by seven pushes and an explicit sub rsp, 40h<\/code>, so we need to add 38h + 40h<\/code> to the current stack pointer to get back to what the stack pointer was at the start of the function, and then we can add the offset of 8 to that result. The value stored there matches what’s in r14<\/code>, which is a nice little confirmation that things are not too far gone.<\/p>\n
Dumping the two pointers at r14<\/code> gives us the exception record and the context record. Let’s switch to the context in the context record:<\/p>\n
0:000> .cxr 000000a5`a7c8e6c0\r\nrax=00007fff3a1c4480 rbx=00007fff3a1c4480 rcx=00000285a6c5e6e0\r\nrdx=000000a5a7c8f570 rsi=000000a5a7c8f500 rdi=00007fff40e6c6a8\r\nrip=00007fff40c2f2ca rsp=000000a5a7c8f480 rbp=000000a5a7c8f530\r\n r8=000000a5a7c8f538  r9=0000000000000003 r10=baac1f10365eb170\r\nr11=4201100001040004 r12=0000000000000008 r13=00000285a6c4b708\r\nr14=0000000000000001 r15=deaddeaddeaddead\r\niopl=0         nv up ei pl zr na po nc\r\ncs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00010246\r\ncombase!CStdMarshal::DisconnectSrvIPIDs::__l35::<lambda_03ceb3c306c371a8ea5da27fc98e7b7c>::operator()+0x11:\r\n00007fff`40c2f2ca 488b4010        mov     rax,qword ptr [rax+10h] ds:00007fff`3a1c4490=????????????????\r\n0:000>\r\n<\/pre>\n
We are calling the Release method on a COM object because the proxy is disconnecting from it. (Since this a 64-bit system, the offsets are 08h<\/code> for AddRef<\/code> and 10h<\/code> for Release<\/code>.)<\/p>\n
We can look at the vtable address to see what this object is.<\/p>\n
0:000> ln @rax\r\n(00007ff8`1a464480)   <Unloaded_windows.serviceframework.widget>+0x14480\r\n<\/pre>\n
As expected, this vtable came from an unloaded module. The system keeps track of the most recently unloaded modules, but the buffer for the file name is fixed in size (to avoid memory allocations). If the name of the DLL were reasonably short, it would all fit into the buffer, and you could use !reload \/unl name.dll<\/code> to tell the debugger to pretend that name.dll<\/code> were still in memory so you could resolve addresses within it.<\/p>\n
Unfortunately, windows.service\u00adframework.widget\u00adservice.dll<\/code> is too long to fit in the buffer, so its name gets truncated, and the debugger can’t recover it.<\/p>\n
We’ll have to resolve the symbol manually\u00b9 using  a technique I discussed some time ago<\/a>: Loading the module as if were a dump file and fixing up the addresses.<\/p>\n
C:\\> ntsd -z windows.serviceframework.widgetservice.dll\r\n...\r\nModLoad: 00000001`80000000 00000001`8001f000 windows.serviceframework.widgetservice.dll\r\nwindows_serviceframework_widgetservice!_DllMainCRTStartup:\r\n00000001`80010c70 48895c2408      mov     qword ptr [rsp+8],rbx ss:00000000`00000008=????????????????\r\n0:000> ln 00000001`80000000+14480\r\n(00000001`80014480)   windows_serviceframework_widgetservice!winrt::impl::produce\r\n                         <winrt::Windows::ServiceFramework::WidgetService::implementation::ColorChangedEventArgs,\r\n                          winrt::Windows::ServiceFramework::WidgetService::IColorChangedEventArgs>::`vftable'\r\n<\/pre>\n
Aha, so this object is a Color\u00adChanged\u00adEvent\u00adArgs<\/code> object, and we see that it is implemented in C++\/WinRT.<\/p>\n
Services that are also COM servers  use COM custom contexts so they can disconnect all their objects prior to being unloaded<\/a>. For this trick to work, all the interfaces they expose to clients must be marshalable, and the objects themselves must not be free-threaded. If the objects are free-threaded (also known as agile<\/i>, short for apartment-agile), then the request for a marshaler would produce the free-threaded marshaler, which says, “Don’t worry about marshaling me. You can just take me from any context to any other context without having to do anything special.” But this is the opposite of what you want with an object provided by a service DLL, since you want those objects to stay inside the custom context so you can disconnect them at unload.<\/p>\n
C++\/WinRT objects are free-threaded by default. This particular component was careful to mark its main object with the non_agile<\/code> marker type, thereby preventing it from being free-threaded. However, it forgot to mark some of its helper classes as non_agile<\/code>, and it is one of those helper classes that escaped the custom COM context and therefore escaped being run down when all objects in the context were disconnected.<\/p>\n
The fix was to make another pass through the objects offered by the DLL and make sure all of the ones used by the service are marked as non-agile. The unit tests for these helper classes were updated to verify that they are not agile, with the hope that if somebody introduces a new helper class, they will copy an existing unit test to use as a starting point and therefore will copy the agility test.<\/p>\n
\u00b9 In retrospect, I probably could have done<\/p>\n
.reload windows.serviceframework.widgetservice.dll=0x00007ff8`1a450000\r\n<\/pre>\n
to tell the debugger to pretend that a DLL was loaded in memory at a particular address.<\/p>\n","protected":false},"excerpt":{"rendered":"
The great escape from the confines of the custom COM context.<\/p>\n","protected":false},"author":1069,"featured_media":111744,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[25],"class_list":["post-104684","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-code"],"acf":[],"blog_post_summary":"
The great escape from the confines of the custom COM context.<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/104684","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/users\/1069"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/comments?post=104684"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/104684\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media\/111744"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media?parent=104684"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=104684"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=104684"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}