{"id":109621,"date":"2024-04-05T07:00:00","date_gmt":"2024-04-05T14:00:00","guid":{"rendered":"https:\/\/devblogs.microsoft.com\/oldnewthing\/?p=109621"},"modified":"2024-04-05T10:25:56","modified_gmt":"2024-04-05T17:25:56","slug":"20240405-00","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20240405-00\/?p=109621","title":{"rendered":"The case of the exception that a catch (…)<\/CODE> didn’t catch"},"content":{"rendered":"

A customer thought they fixed a bug, but they were still getting crashes from it.<\/p>\n

According to the !analyze<\/code> output, the problem was coming from this stack:<\/p>\n

contoso!winrt::hresult_error::hresult_error+0x143\r\ncontoso!winrt::throw_hresult+0x132\r\ncontoso!winrt::impl::consume_LitWare_IIconProvider\r\n    <winrt::LitWare::IIconProvider>::LoadIcon+0x3b\r\ncontoso!winrt::Contoso::implementation::IconDataModel::\r\n    ReloadIcon$_ResumeCoro$1+0x214\r\ncontoso!winrt::impl::resume_background_callback+0x10\r\nntdll!TppSimplepExecuteCallback+0xa3\r\nntdll!TppWorkerThread+0x8f6\r\nkernel32!BaseThreadInitThunk+0x1d\r\nntdll!RtlUserThreadStart+0x28\r\n<\/pre>\n
This was puzzling because “We already fixed that bug!” The file version number and timestamp confirm that the code for Reload\u00adIcon<\/code> catches the exception:<\/p>\n
    try\r\n    {\r\n        icon = m_provider.LoadIcon(); \/\/ \u21d0 blamed frame\r\n    }\r\n    catch(...)\r\n    {\r\n        \/\/ There was a problem getting the new icon.\r\n        \/\/ Just stick with the old one.\r\n        LOG_CAUGHT_EXCEPTION();\r\n        co_return;\r\n    }\r\n<\/pre>\n
Let’s look at the stack at the point of the crash:<\/p>\n
KERNELBASE!RaiseFailFastException+0x152\r\ncombase!RoFailFastWithErrorContextInternal2+0x4d9\r\ncontoso!wil::details::FailfastWithContextCallback+0xc1\r\ncontoso!wil::details::WilFailFast+0x47\r\ncontoso!wil::details::ReportFailure_NoReturn<3>+0x2df\r\ncontoso!wil::details::ReportFailure_Base<3,0>+0x30\r\ncontoso!wil::details::ReportFailure_CaughtExceptionCommonNoReturnBase<3>+0xa7\r\ncontoso!wil::details::ReportFailure_CaughtExceptionCommon+0x22\r\ncontoso!wil::details::ReportFailure_CaughtException<3>+0x40\r\ncontoso!wil::details::in1diag3::FailFast_CaughtException+0x13\r\ncontoso!`<lambda_f370031fe3623a0b308de0bbdeb2db76>::operator()'::`1'::catch$2+0x22\r\nucrtbase!_CallSettingFrame_LookupContinuationIndex+0x20\r\nucrtbase!__FrameHandler4::CxxCallCatchBlock+0x115\r\nntdll!RcFrameConsolidation+0x6\r\ncontoso!<lambda_f370031fe3623a0b308de0bbdeb2db76>::operator()+0x1a\r\ncontoso!std::invoke+0x24\r\ncontoso!std::_Invoker_ret<void,1>::_Call+0x24\r\ncontoso!std::_Func_impl_no_alloc<<lambda_f370031fe3623a0b308de0bbdeb2db76>,\r\n    void,Concurrency::task<void> >::_Do_call+0x28\r\ncontoso!std::_Func_class<void,Concurrency::task<void> >::operator()+0x31\r\ncontoso!Concurrency::details::_MakeTToUnitFunc::__l2::\r\n    <lambda_64124396551846798083ef48cd389b4a>::operator()+0x46\r\ncontoso!std::invoke+0x66\r\ncontoso!std::_Invoker_ret<unsigned char,0>::_Call+0x66\r\ncontoso!std::_Func_impl_no_alloc<<lambda_64124396551846798083ef48cd389b4a>,\r\n    unsigned char,Concurrency::task<void> >::_Do_call+0x72\r\ncontoso!std::_Func_class<unsigned char,Concurrency::task<void> >::\r\n    operator()+0x32\r\ncontoso!Concurrency::task<void>::_ContinuationTaskHandle<void,\r\n    void,std::function<void __cdecl(Concurrency::task<void>)>,\r\n    std::integral_constant<bool,1>,Concurrency::details::_TypeSelectorNoAsync>::\r\n    _LogWorkItemAndInvokeUserLambda<std::function<unsigned char __cdecl(\r\n    Concurrency::task<void>)>,Concurrency::task<void> >+0x8b\r\ncontoso!Concurrency::task<void>::_ContinuationTaskHandle<void,\r\n    void,std::function<void __cdecl(Concurrency::task<void>)>,\r\n    std::integral_constant<bool,1>,Concurrency::details::_TypeSelectorNoAsync>::\r\n    _Continue+0x8c\r\ncontoso!Concurrency::task<void>::_ContinuationTaskHandle<void,\r\n    void,std::function<void __cdecl(Concurrency::task<void>)>,\r\n    std::integral_constant<bool,1>,Concurrency::details::_TypeSelectorNoAsync>::\r\n    _Perform+0x8\r\ncontoso!Concurrency::details::_PPLTaskHandle<unsigned char,Concurrency::task<\r\n    void>::_ContinuationTaskHandle<void,void,std::function<\r\n    void __cdecl(Concurrency::task<void>)>,std::integral_constant<bool,1>,\r\n    Concurrency::details::_TypeSelectorNoAsync>,\r\n    Concurrency::details::_ContinuationTaskHandleBase>::invoke+0x37\r\ncontoso!Concurrency::details::_TaskProcHandle::_RunChoreBridge+0x25\r\ncontoso!Concurrency::details::_DefaultPPLTaskScheduler::_PPLTaskChore::\r\n    _Callback+0x26\r\nmsvcp140!Concurrency::details::`anonymous namespace'::\r\n    _Task_scheduler_callback+0x5d\r\nntdll!TppWorkpExecuteCallback+0x13a\r\nntdll!TppWorkerThread+0x8f6\r\nkernel32!BaseThreadInitThunk+0x1d\r\nntdll!RtlUserThreadStart+0x28\r\n<\/pre>\n
Hey, wait a second, this doesn’t look anything like the stack reported by !analyze<\/code>! What’s going on?<\/p>\n
The !analyze<\/code> used the stack from the first stowed exception. You can dump all of the stowed exceptions with the !pde.dse<\/code> command.<\/p>\n
0:076> !pde.dse\r\nStowed Exception Array @ 0x000000002b1ef170\r\n\r\nStowed Exception #1 @ 0x000000001ce068e8\r\n    0x80070005 (FACILITY_WIN32 - Win32 Undecorated Error Codes):\r\n    E_ACCESSDENIED - General access denied error\r\n\r\n    Stack    : 0x2b214de0\r\n    contoso!winrt::hresult_error::hresult_error+0x143\r\n    contoso!winrt::throw_hresult+0x132\r\n    contoso!winrt::impl::consume_LitWare_IIconProvider\r\n        <winrt::LitWare::IIconProvider>::LoadIcon+0x3b\r\n    contoso!winrt::Contoso::implementation::IconDataModel::\r\n        ReloadIcon$_ResumeCoro$1+0x214\r\n    contoso!winrt::impl::resume_background_callback+0x10\r\n    ntdll!TppSimplepExecuteCallback+0xa3\r\n    ntdll!TppWorkerThread+0x8f6\r\n    kernel32!BaseThreadInitThunk+0x1d\r\n    ntdll!RtlUserThreadStart+0x28\r\n\r\nStowed Exception #2 @ 0x000000001ce02378\r\n    0x80070005 (FACILITY_WIN32 - Win32 Undecorated Error Codes):\r\n    E_ACCESSDENIED - General access denied error\r\n\r\n    Stack    : 0x12cda890\r\n    litware!winrt::hresult_error::hresult_error+0x12c\r\n    litware!winrt::throw_hresult+0x83\r\n    litware!winrt::LitWare::implementation::IconProvider::LoadIcon+0x90\r\n    litware!winrt::impl::produce<winrt::LitWare::implementation::IconProvider,\r\n        winrt::LitWare::IIconProvider>::LoadIcon+0x1b\r\n    contoso!winrt::impl::consume_LitWare_IIconProvider\r\n        <winrt::LitWare::IIconProvider>::LoadIcon+0x3b\r\n    contoso!winrt::Contoso::implementation::IconDataModel::\r\n        ReloadIcon$_ResumeCoro$1+0x214\r\n    contoso!winrt::impl::resume_background_callback+0x10\r\n    ntdll!TppSimplepExecuteCallback+0xa3\r\n    ntdll!TppWorkerThread+0x8f6\r\n    kernel32!BaseThreadInitThunk+0x1d\r\n    ntdll!RtlUserThreadStart+0x28\r\n\r\nStowed Exception #3 @ 0x000000001ce04fa8\r\n    0x80070005 (FACILITY_WIN32 - Win32 Undecorated Error Codes):\r\n    E_ACCESSDENIED - General access denied error\r\n\r\n    Stack    : 0x1d94b410\r\n    combase!RoOriginateError+0x51\r\n    contoso!wil::details::RaiseRoOriginateOnWilExceptions+0x137\r\n    contoso!wil::details::ReportFailure_Return<1>+0x1b8\r\n    contoso!wil::details::ReportFailure_Win32<1>+0x70\r\n    contoso!wil::details::in1diag3::Return_Win32+0x18\r\n    contoso!Internal::ContosoSettingsStorage::Save+0xdc729\r\n    contoso!Internal::ContosoSettings::SaveToDefaultLocalStorage+0xf1\r\n    contoso!Internal::ContosoSettings::Save+0x4ef\r\n    contoso!Contoso::AppSettings::save+0x4ef\r\n    contoso!std::_Func_impl_no_alloc<<lambda_f4300885c0b58e31cf789c4999ed9d7a>,\r\n        void>::_Do_call+0x2b\r\n    contoso!std::_Func_impl_no_alloc<<lambda_052e919cc0e5399df76dff3972c0cac1>,\r\n        unsigned char>::_Do_call+0x28\r\n    contoso!Concurrency::task<unsigned char>::_InitialTaskHandle<void,\r\n        <lambda_f4300885c0b58e31cf789c4999ed9d7a>,\r\n        Concurrency::details::_TypeSelectorNoAsync>::_Init+0xc3\r\n    contoso!Concurrency::details::_PPLTaskHandle<unsigned char,\r\n        Concurrency::task<unsigned char>::_InitialTaskHandle<void,\r\n        <lambda_f4300885c0b58e31cf789c4999ed9d7a>,\r\n        Concurrency::details::_TypeSelectorNoAsync>,\r\n        Concurrency::details::_TaskProcHandle>::invoke+0x55\r\n    contoso!Concurrency::details::_TaskProcHandle::_RunChoreBridge+0x25\r\n    contoso!Concurrency::details::_DefaultPPLTaskScheduler::_PPLTaskChore::\r\n        _Callback+0x26\r\n    msvcp140!Concurrency::details::`anonymous namespace'::\r\n        _Task_scheduler_callback+0x5d\r\n    ntdll!TppWorkpExecuteCallback+0x13a\r\n    ntdll!TppWorkerThread+0x686\r\n    kernel32!BaseThreadInitThunk+0x10\r\n    ntdll!RtlUserThreadStart+0x2b\r\n<\/pre>\n
Now things are starting to come together.<\/p>\n
The rule of thumb for throwing Windows Runtime exceptions is that before you throw the exception or return the failure HRESULT<\/code>, you call RoOriginateError<\/code> to capture the stack and other context. It is common when working with the Windows Runtime that the exception is caught and saved (“stowed”), usually in an IAsyncAction<\/code> or similar interface, and then later, when the caller does a co_await<\/code> or similar operation. the exception is rethrown.<\/p>\n
When the exception is rethrown, the original stack has already unwound, so there is nothing on the stack to trace. Calling RoOriginateError<\/code> captures the stack at the point of failure before it’s too late. This information can then be used to “stitch together” the exception lifetime, starting with the code that threw the exception and ending with the code that tried (and failed) to catch it.<\/p>\n
The system does this stitching by storing error history in per-thread data, allowing components to capture that history and transfer it to another thread when a task’s error state moves between threads, and looking for errors with the same HRESULT<\/code>s.\u00b9 If there is a recent captured stack for an HRESULT<\/code> that matches the HRESULT<\/code> of the exception that went unhandled, then the system says, “I bet these two belong together.”<\/p>\n
Usually, all of this stack-stitching works out well because our API design principles say that exceptions should not be thrown for recoverable errors. This means that there generally not a lot of exception traffic, so the rate of false positives is low.<\/p>\n
But in this case, we had a false positive: The IconDataModel<\/code> called IconProvider::LoadIcon()<\/code>, which failed with E_ACCESS\u00adDENIED<\/code>. This exception was then caught and handled. We see this from the top two stowed exceptions, using what we learned a little while ago  about stitching together multiple error stacks get a fuller picture of what led to a failure<\/a>.<\/p>\n
In this case, the Icon\u00adProvider::Load\u00adIcon()<\/code> explicitly threw an exception with throw_hresult<\/code> (Stowed Exception #2), which then was converted from a C++ exception to an HRESULT<\/code> at the ABI boundary, and then on the other side, C++\/WinRT turned the HRESULT<\/code> back into an exception and rethrew it (Stowed Exception #1). This rethrown exception was then caught by the catch (...)<\/code>, and that’s the end of that exception.<\/p>\n
That’s not what caused us to crash.<\/p>\n
The current active stack shows that we raised a fail-fast exception from a lambda. The debugger tells us that it’s this lambda:<\/p>\n
void ViewPreferences::SaveChanges()\r\n{\r\n    m_settings.save_async()\r\n    .then([](concurrency::task<void> precedingTask) {\r\n        try\r\n        {\r\n            precedingTask.get();\r\n        }\r\n        CATCH_FAIL_FAST();\r\n    });\r\n}\r\n<\/pre>\n
The code saves the settings and fails fast if the operation failed.<\/p>\n
And we see that failure in the third<\/i> stack, the one with Contoso\u00adSettings\u00adStorage::Save<\/code>. That Save<\/code> operation failed with E_ACCESS\u00adDENIED<\/code>, and it was logged in the failure history.<\/p>\n
What happened is that there were two<\/i> E_ACCESS\u00adDENIED<\/code> errors that occurred at roughly the same time, and !analyze<\/code>‘s attempt to figure out which stacks belonged to which sequence was not completely successful, and it thought that the current failure matched up with the m_provider.LoadIcon()<\/code> failure. But we, using our human brains, saw that the m_provider.LoadIcon()<\/code> exception was handled, and the real culprit was the Stowed Exception #3.<\/p>\n
\u00b9 You can call the function Ro\u00adTransform\u00adError<\/code> if your code receives one error code and returns a different one. This tells COM error-tracking that these two error sequences should be stitched together to form one large error sequence.<\/p>\n","protected":false},"excerpt":{"rendered":"
Reconstructing a false history.<\/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-109621","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-code"],"acf":[],"blog_post_summary":"
Reconstructing a false history.<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/109621","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=109621"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/109621\/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=109621"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=109621"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=109621"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}