v1.1 SDK throws an access violation from MddBootstrapInitialize's logging code if no matching packages are installed

[fredemmott]

Describe the bug

My app currently calls MddBootstrapInitialize() when running unpackaged:

https://github.com/fredemmott/OpenKneeboard/blob/794c53568b34f18443027c43135b7a90e5ce47eb/src/app/app-winui3/App.xaml.cpp#L200-L204

After upgrading from 1.0 to 1.1 - changing the c++/winrt package to 2.0.220418.1 (the latest version is compatible with WinUI3 when building with C++20) and windows app SDK 1.1.0, this has the following output:

D:\a\_work\1\s\BuildOutput\Release\x64\WindowsAppRuntime_DLL\WindowsAppRuntimeInsights.h(53)\Microsoft.WindowsAppRuntime.Bootstrap.dll!00007FF981FE24DB: (caller: 00007FF981FDE1C6) LogHr(1) tid(5c44) 8007007E The specified module could not be found.
    Msg:[Unable to load resource dll. Microsoft.WindowsAppRuntime.Insights.Resource.dll] 
D:\a\_work\1\s\dev\WindowsAppRuntime_BootstrapDLL\MddBootstrap.cpp(776)\Microsoft.WindowsAppRuntime.Bootstrap.dll!00007FF981FDB0D9: (caller: 00007FF981FD9C2F) LogHr(2) tid(5c44) 80040010 Object is not in any of the inplace active states
    Msg:[Bootstrap.Intitialize: Scanning packages for Major.Minor=1.1, Tag=, MinVersion=1000.516.2156.0] CallContext:[\Initialize] 
Exception thrown at 0x00007FF981FE4403 (Microsoft.WindowsAppRuntime.Bootstrap.dll) in OpenKneeboardApp.exe: 0xC0000005: Access violation writing location 0x00007FF981FF6716.

windbg points here:

void MddBootstrap_StopActivity(
    const std::string failureType,
    const bool isActivityRunning,
    const GUID *activityId,
    const WindowsAppRuntime::MddBootstrap::Activity::Context& activityContext,
    const wil::FailureInfo& failure)
{
    MddBootstrap_WriteEventWithActivity(*failureType.c_str(), activityId);

...

called from:

    THROW_HR_IF_MSG(HRESULT_FROM_WIN32(ERROR_NO_MATCH), !foundAny, "Enumeration: %ls", criteria.get());
    (void)LOG_HR_MSG(MDD_E_BOOTSTRAP_INITIALIZE_DDLM_FOUND,
                     "Bootstrap.Intitialize: %ls best matches the criteria (%ls) of %d packages scanned",
                     bestFitPackageFullName.c_str(), criteria.get(), packagesScanned);

bestFitPackageFullName is a null handle.

Steps to reproduce the bug

1. Grab fredemmott/openkneeboard at rev 794c53568b34f18443027c43135b7a90e5ce47eb
2. Apply https://gist.github.com/fredemmott/96216c79d2e0496e128a7923a6ac6777 to update windows app SDK and C++/winrt
3. build with cmake in debug mode
4. run app, e.g. build\src\app\app-winui3\msbuild-out-Debug\OpenKneeboardApp.exe

Expected behavior

App should start, or exit cleanly, depending on state of installed packages.

Screenshots

No response

NuGet package version

No response

Packaging type

Unpackaged

Windows version

Windows 10 version 21H2 (19044, November 2021 Update)

IDE

Other

Additional context

• using 1.1.0 nuget package, which isn't in list
• using vscode + cmake

[fredemmott]

• possibly a dupe of WinAppSDK v1.1.0 throws System.AccessViolationException on Unpackaged WinUI 3 apps #2578
• seems likely related to the work on If an 'unpackaged' app is packaged, it silently fails #2216/Rich information on Bootstrap initalization failure #2316

[fredemmott]

• switching to MddBootstrapInitialize2 doesn't fix this...
• forgot to update the PackageDependency in my appxmanifest - this didn't fix it

[fredemmott]

Correction (windbg is giving me off-by-one lines on some frames) -

WindowsAppSDK/dev/WindowsAppRuntime_BootstrapDLL/MddBootstrap.cpp

Line 905 in d1d6daa

THROW_HR_IF_MSG(HRESULT_FROM_WIN32(ERROR_NO_MATCH), !foundAny, "Enumeration: %ls", criteria.get());

is the call that eventually leads to the access violation

[fredemmott]

Also seeing the same if I use the auto-generated auto initializer :(

[fredemmott]

Same with release build.

@sachintaMSFT @DrusTheAxe this part of #2321 seems to likely be the problem:

https://github.com/microsoft/WindowsAppSDK/blob/v1.1.0/dev/WindowsAppRuntime_BootstrapDLL/MddBootstrapTracelogging.cpp#L8-L15

... in combination with ...

https://github.com/microsoft/WindowsAppSDK/blob/v1.1.0/dev/WindowsAppRuntime_BootstrapDLL/MddBootstrapTracelogging.h#L126-L142

windbg says the access violation is:

Microsoft_WindowsAppRuntime_Bootstrap!MddBootstrap_StopActivity+0x93:
00007ff9`c1a14403 88050d230100    mov     byte ptr [Microsoft_WindowsAppRuntime_Bootstrap!_tlgEvent+0xf (00007ff9`c1a26716)],al ds:00007ff9`c1a26716=00
0:000> dt _tlgEvent
   +0x000 _tlgBlobTyp      : 0x6 ''
   +0x001 _tlgChannel      : 0xb ''
   +0x002 _tlgLevel        : 0x5 ''
   +0x003 _tlgOpcode       : 0 ''
   +0x004 _tlgKeyword      : 0
   +0x00c _tlgEvtMetaSize  : 0x30
   +0x00e _tlgEvtTag       : 0 ''
   +0x00f _tlgName         : [1]  ""
   +0x010 _tlgName0        : [5]  ""
   +0x015 _tlgTy0          : 0 ''
   +0x016 _tlgName1        : [8]  ""
   +0x01e _tlgTy1          : 0 ''
   +0x01f _tlgName2        : [5]  ""
   +0x024 _tlgTy2          : 0 ''
   +0x025 _tlgName3        : [5]  ""
   +0x02a _tlgTy3          : 0 ''
   +0x02b _tlgName4        : [7]  ""
   +0x032 _tlgTy4          : 0 ''
   +0x033 _tlgName5        : [8]  ""
   +0x03b _tlgTy5          : 0 ''

If I'm reading that correctly, writing to _tlgEvent._tlgName within the ETW macros is failing

[fredemmott]

Yeah, this seems wrong:

    MddBootstrap_WriteEventWithActivity(*failureType.c_str(), activityId);

This passes through to TraceLoggingWriteActivity, with the first arg becoming the event name.

1. It should be a C string, i.e. char*, not a char
2. The documentation notes "This must be a string literal and not a variable"

Both are likely problematic as the macro uses sizeof(eventname) which is the length of the string when using a literal, but is currently 1 (as it's a char), and would be 4 or 8 if it was c_str(), instead of the length of the string as expected.

[fredemmott]

The exception being thrown is 0x80070491 (There was no match for the specified key in the index.) - "0x13b81fd8f0 : "Enumeration: Major.Minor=1.1, Tag=, MinVersion=1000.516.2156.0"" for "microsoft.winappruntime.ddlm."

Proximal cause is a missing ddlm package, filing a ticket for that - but regardless of the trigger, the event logging shouldn't crash: the bootstrapper is meant to report/log missing packages.

[riverar]

So looks like you didn't install the latest runtimes?

[fredemmott]

@riverar it was partially installed automatically by windows/the store, and the runtime installer will not install missing components on top of a partial install - filed #2595

That said, the missing packages are orthogonal to this issue: the purpose of the event logging and the existence of MddBootstrapInitialize2() is to provide information about what is broken when dependencies aren't installed - so they should expect to 'work' (i.e. log/present information, not crash) - when parts of the windows app runtime are not installed.

[riverar]

Sounds good. Is this a fair summary?

• Runtimes not being cross-channel (Store, loose installer, etc.) serviced correctly (think @DrusTheAxe already fixed that one)
• Telemetry crashing in failure scenarios

[fredemmott]

Runtimes not being cross-channel (Store, loose installer, etc.) serviced correctly

Maybe - this wording is too specific for me to be certain :)

Telemetry crashing in failure scenarios

Yep - in particular, variables can't be passed as ETW event names, and the bootstrapper's logging attempts to do this.

[DrusTheAxe]

Ouch! Great catch, thanks for the analysis! Working up a fix as we speak, will get it into the servicing queue ASAP

Thanks!

[riverar]

@DrusTheAxe Beware of the

D:\a\_work\1\s\dev\WindowsAppRuntime_BootstrapDLL\MddBootstrap.cpp(536)\Microsoft.WindowsAppRuntime.Bootstrap.dll!00007FFE5F8938F9: (caller: 00007FFE5F89244F) LogHr(1) tid(aaec) 80040010 Object is not in any of the inplace active states
    Msg:[Bootstrap.Intitialize: Scanning packages for Major.Minor=1.1, Tag=, MinVersion=1000.516.2156.0] 

This seems to be coming from the wil helper https://github.com/microsoft/WindowsAppSDK/blob/v1.1.0/dev/WindowsAppRuntime_BootstrapDLL/MddBootstrap.cpp#L536. Then because package enumeration failed, the installed candidate package is not found.

[gabbybilka]

Fixed in Windows App SDK 1.1.2, see release notes for more info.