Improved Logging v3 (#4372)

* Revert "Better logging support, replaces LOG_HR_MSG with DebugLog (#4271)" This reverts commit 789ad81e67. * Removed dead code * Added coding guidelines for error handling and logging (doc current / expected practices) * Change LOG_HR* misuse for non-failure (informational) purposes to proper TraceLoggingWrite() * Optimized logging (TraceLogging fields instead of pre-formatting a string). Optimized bestFit tracking collapsing 1st match and better-match relying on DDLM version will always be >0.0.0.0 (kudos to Pratik for the optimization). * Incorporated feedback
2024-05-01 13:48:47 -07:00 · 2024-05-01 13:48:47 -07:00 · cbcf936092
--- a/dev/Common/Common.vcxitems
+++ b/dev/Common/Common.vcxitems
@ -30,6 +30,5 @@
    <ClInclude Include="$(MSBuildThisFileDirectory)WindowsAppRuntime.SelfContained.h" />
    <ClInclude Include="$(MSBuildThisFileDirectory)WindowsAppRuntime.VersionInfo.h" />
    <ClInclude Include="$(MSBuildThisFileDirectory)winrt_WindowsAppRuntime.h" />
-    <ClInclude Include="$(MSBuildThisFileDirectory)Logging.h" />
  </ItemGroup>
 </Project>
--- a/dev/Common/Logging.h
+++ b/dev/Common/Logging.h
@ -1,26 +0,0 @@
-// Copyright (c) Microsoft Corporation and Contributors.
-// Licensed under the MIT License.
-
-#pragma once
-
-#include <Windows.h>
-#include <source_location>
-#include <sstream>
-
-namespace Common::Logging
-{
-    // use std::format in msg parameter to have a printf like varargs syntax for the debug message
-    inline void DebugLog(const wchar_t* msg,  const std::source_location location = std::source_location::current())
-    {
-        std::wstringstream filename ;
-        filename << location.file_name(); // converting char to wstring (and wchar_t implicitly)
-        // format is "foo.cpp (66) : debug message"
-        const std::wstring printmsg = std::format(L"{} ({}) : {}\n", filename.str(), location.line(), msg);
-        OutputDebugStringW(printmsg.c_str());
-    }
-
-    inline void DebugLog(const std::wstring& msg, const std::source_location location = std::source_location::current())
-    {
-        DebugLog(msg.c_str(), location);
-    }
-}
--- a/dev/DynamicDependency/API/DataStore.cpp
+++ b/dev/DynamicDependency/API/DataStore.cpp
@ -2,11 +2,12 @@
 // Licensed under the MIT License.

 #include "pch.h"
+
 #include "DataStore.h"
-#include "Logging.h"

 #include "DynamicDependencyDataStore_h.h"
 #include "winrt_WindowsAppRuntime.h"
+
 #include <wil/winrt.h>

 #include <shlobj.h>
@ -207,48 +208,5 @@ std::filesystem::path MddCore::DataStore::GetDataStorePathForUserViaApplicationD

 std::wstring MddCore::DataStore::GetWindowsAppRuntimeMainPackageFamilyName()
 {
-#if 1
    return ::WindowsAppRuntime::VersionInfo::Main::GetPackageFamilyName();
-#else
-    const UINT32 flags{ PACKAGE_FILTER_HEAD | PACKAGE_FILTER_DIRECT | PACKAGE_FILTER_STATIC | PACKAGE_FILTER_DYNAMIC | PACKAGE_INFORMATION_BASIC };
-    uint32_t packageInfosCount{};
-    const PACKAGE_INFO* packageInfos{};
-    wil::unique_cotaskmem_ptr<BYTE[]> buffer;
-    THROW_IF_FAILED(::AppModel::PackageGraph::GetCurrentPackageGraph(flags, packageInfosCount, packageInfos, buffer));
-    for (uint32_t index=0; index < packageInfosCount; ++index)
-    {
-        // Check the PublisherId
-        const auto& packageInfo{ packageInfos[index] };
-        const auto& packageId{ packageInfo.packageId };
-        const auto packagePublisherId{ packageId.publisherId };
-        PCWSTR c_windowsAppRuntimePublisherId{ L"8wekyb3d8bbwe" };
-        if (CompareStringOrdinal(packagePublisherId, -1, c_windowsAppRuntimePublisherId, -1, TRUE) != CSTR_EQUAL)
-        {
-            continue;
-        }
-
-        // Framework package's name in the package graph is Microsoft.WindowsAppRuntime.<major>.<minor>
-        const auto packageName{ packageId.name };
-        const auto packageNameLength{ wcslen(packageName) };
-        PCWSTR c_windowsAppRuntimeNamePrefix{ L"Microsoft.WindowsAppRuntime." };
-        const auto c_windowsAppRuntimeNamePrefixLength{ ARRAYSIZE(L"Microsoft.WindowsAppRuntime.") - 1 };
-        if (packageNameLength < c_windowsAppRuntimeNamePrefixLength)
-        {
-            continue;
-        }
-        if (CompareStringOrdinal(packageName, c_windowsAppRuntimeNamePrefixLength, c_windowsAppRuntimeNamePrefix, c_windowsAppRuntimeNamePrefixLength, TRUE) != CSTR_EQUAL)
-        {
-            continue;
-        }
-        PCWSTR packageNameSuffix{ packageName + c_windowsAppRuntimeNamePrefixLength };
-
-        // Gotcha!
-        WCHAR mainPackageFamilyName[PACKAGE_FAMILY_NAME_MAX_LENGTH + 1]{};
-        wsprintf(mainPackageFamilyName, L"MicrosoftCorporationII.WinAppRuntime.Main.%s_8wekyb3d8bbwe", packageNameSuffix);
-        return std::wstring(mainPackageFamilyName);
-    }
-
-    // Didn't find the Windows App SDK framework package in the package graph. Can't determine the package identity!
-    THROW_HR(MDD_E_WINDOWSAPPRUNTIME_NOT_IN_PACKAGE_GRAPH);
-#endif
 }
--- a/dev/DynamicDependency/API/MsixDynamicDependency.h
+++ b/dev/DynamicDependency/API/MsixDynamicDependency.h
@ -8,10 +8,18 @@

 #include <stdint.h>

-// MSIX Dynamic Dependency HRESULT: Data Store not found (Windows App Runtime's Main package not registered?)
+/// MSIX Dynamic Dependency HRESULT: Windows App Runtime is not in the package graph.
+#define MDD_E_WINDOWSAPPRUNTIME_NOT_IN_PACKAGE_GRAPH    _HRESULT_TYPEDEF_(0x80040001L)
+
+/// MSIX Dynamic Dependency HRESULT: Data Store not found (Windows App Runtime's Main package not registered?)
 #define MDD_E_WINDOWSAPPRUNTIME_DATASTORE_NOT_FOUND     _HRESULT_TYPEDEF_(0x80040002L)

-// MSIX Dynamic Dependency: Bootstrap initialization request is incompatible with current Bootstrap initialization state.
+// Reserved: _HRESULT_TYPEDEF_(0x80040010L)
+// Reserved: _HRESULT_TYPEDEF_(0x80040011L)
+// Reserved: _HRESULT_TYPEDEF_(0x80040012L)
+// Reserved: _HRESULT_TYPEDEF_(0x80040013L)
+
+/// MSIX Dynamic Dependency: Bootstrap initialization request is incompatible with current Bootstrap initialization state.
 #define MDD_E_BOOTSTRAP_INITIALIZE_INCOMPATIBLE         _HRESULT_TYPEDEF_(0x80040014L)

 #if defined(__cplusplus)
--- a/dev/PackageManager/API/M.W.M.D.PackageDeploymentManager.cpp
+++ b/dev/PackageManager/API/M.W.M.D.PackageDeploymentManager.cpp
@ -6,10 +6,10 @@
 #include "Microsoft.Windows.Management.Deployment.PackageDeploymentManager.g.cpp"

 #include "M.W.M.D.PackageDeploymentResult.h"
+#include "MsixPackageManager.h"
 #include "PackageDeploymentResolver.h"

 #include "PackageManagerTelemetry.h"
-#include "logging.h"

 static_assert(static_cast<int>(winrt::Microsoft::Windows::Management::Deployment::StubPackageOption::Default) == static_cast<int>(winrt::Windows::Management::Deployment::StubPackageOption::Default),
              "winrt::Microsoft::Windows::Management::Deployment::StubPackageOption::Default != winrt::Windows::Management::Deployment::StubPackageOption::Default");
@ -54,14 +54,16 @@ namespace winrt::Microsoft::Windows::Management::Deployment::implementation
        {
            if (!IsReady(packageSetItem))
            {
-                Common::Logging::DebugLog(std::format(L"Id={} PackageFamilyName={} MinVersion={}.{}.{}.{} ArchitectureFilter:0x{}",
-                            packageSetItem.Id().c_str(),
-                            packageSetItem.PackageFamilyName().c_str(),
-                            packageSetItem.MinVersion().Major,
-                            packageSetItem.MinVersion().Minor,
-                            packageSetItem.MinVersion().Build,
-                            packageSetItem.MinVersion().Revision,
-                            static_cast<std::uint32_t>(packageSetItem.ProcessorArchitectureFilter())));
+                const ::AppModel::Identity::PackageVersion minVersion{ packageSetItem.MinVersion() };
+                TraceLoggingWrite(
+                    PackageManagementTelemetryProvider::Provider(),
+                    "PackageDeployment.Resolver.Scan.NoMatch.Version",
+                    TraceLoggingWideString(packageSetItem.Id().c_str(), "Criteria.Id"),
+                    TraceLoggingWideString(packageSetItem.PackageFamilyName().c_str(), "Criteria.PackageFamilyName"),
+                    TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+                    TraceLoggingHexInt32(static_cast<std::int32_t>(packageSetItem.ProcessorArchitectureFilter()), "Criteria.ArchitectureFilter"),
+                    TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+                    TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
                return false;
            }
        }
--- a/dev/PackageManager/API/MsixPackageManager.h
+++ b/dev/PackageManager/API/MsixPackageManager.h
@ -0,0 +1,12 @@
+// Copyright (c) Microsoft Corporation and Contributors.
+// Licensed under the MIT License.
+
+#if !defined(MSIXPACKAGEMANAGER_H)
+#define MSIXPACKAGEMANAGER_H
+
+// Reserved: _HRESULT_TYPEDEF_(0x80040301L)
+// Reserved: _HRESULT_TYPEDEF_(0x80040302L)
+// Reserved: _HRESULT_TYPEDEF_(0x80040303L)
+// Reserved: _HRESULT_TYPEDEF_(0x80040304L)
+
+#endif // MSIXPACKAGEMANAGER_H
--- a/dev/PackageManager/API/PackageDeploymentResolver.cpp
+++ b/dev/PackageManager/API/PackageDeploymentResolver.cpp
@ -6,7 +6,9 @@
 #include <winrt/Microsoft.Windows.ApplicationModel.DynamicDependency.h>

 #include "PackageDeploymentResolver.h"
-#include "logging.h"
+
+#include "MsixPackageManager.h"
+#include "PackageManagerTelemetry.h"

 namespace Microsoft::Windows::ApplicationModel::PackageDeploymentResolver
 {
@ -161,7 +163,7 @@ bool Microsoft::Windows::ApplicationModel::PackageDeploymentResolver::FindAny(
    winrt::hstring packageFullName{ Find(packageManager, packageFamilyName, minVersion, processorArchitectureFilter, true) };
    return !packageFullName.empty();
 }
-//TODO : this looks to be very similar to MddBootstrap.cpp FindDDLMViaEnumeration(). Good candidate for refactoring.
+
 winrt::hstring Microsoft::Windows::ApplicationModel::PackageDeploymentResolver::Find(
    const winrt::Windows::Management::Deployment::PackageManager& packageManager,
    const winrt::hstring& packageFamilyName,
@ -179,12 +181,14 @@ winrt::hstring Microsoft::Windows::ApplicationModel::PackageDeploymentResolver::
    auto packages{ packageManager.FindPackagesForUserWithPackageTypes(winrt::hstring(), packageFamilyName, packageTypes) };

    // Find the/any match
-    auto criteria{ wil::str_printf<wil::unique_cotaskmem_string>(L"PackageFamilyName=%ls MinVersion=%hu.%hu.%hu.%hu ArchitectureFilter:0x%X",
-                                                                 packageFamilyName.c_str(),
-                                                                 minVersion.Major, minVersion.Minor,
-                                                                 minVersion.Build, minVersion.Revision,
-                                                                 static_cast<std::uint32_t>(processorArchitectureFilter)) };
-    Common::Logging::DebugLog(std::format(L"PackageDeploymentResolver: Scanning packages ({})", criteria.get()));
+    TraceLoggingWrite(
+        PackageManagementTelemetryProvider::Provider(),
+        "PackageDeployment.Resolver.Scan",
+        TraceLoggingWideString(packageFamilyName.c_str(), "Criteria.PackageFamilyName"),
+        TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+        TraceLoggingHexInt32(static_cast<std::int32_t>(processorArchitectureFilter), "Criteria.ArchitectureFilter"),
+        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+        TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
    if (packages)
    {
        for (const winrt::Windows::ApplicationModel::Package& candidate : packages)
@ -201,6 +205,15 @@ winrt::hstring Microsoft::Windows::ApplicationModel::PackageDeploymentResolver::
            auto candidateFullName{ packageId.FullName() };
            if (candidateVersion < minVersion)
            {
+                TraceLoggingWrite(
+                    PackageManagementTelemetryProvider::Provider(),
+                    "PackageDeployment.Resolver.Scan.NoMatch.Version",
+                    TraceLoggingWideString(candidateFullName.c_str(), "PackageFullName"),
+                    TraceLoggingWideString(packageFamilyName.c_str(), "Criteria.PackageFamilyName"),
+                    TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+                    TraceLoggingHexInt32(static_cast<std::int32_t>(processorArchitectureFilter), "Criteria.ArchitectureFilter"),
+                    TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+                    TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
                continue;
            }

@ -220,7 +233,18 @@ winrt::hstring Microsoft::Windows::ApplicationModel::PackageDeploymentResolver::
                const auto supportedArchitectures{ GetSystemSupportedArchitectures(nativeMachine) };
                if (!IsArchitectureInArchitectures(candidateArchitecture, supportedArchitectures))
                {
-                    // package arch didn't match anything from system supported architectures
+                    TraceLoggingWrite(
+                        PackageManagementTelemetryProvider::Provider(),
+                        "PackageDeployment.Resolver.Scan.NoMatch.Architecture",
+                        TraceLoggingWideString(candidateFullName.c_str(), "PackageFullName"),
+                        TraceLoggingWideString(packageFamilyName.c_str(), "Criteria.PackageFamilyName"),
+                        TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+                        TraceLoggingHexInt32(static_cast<std::int32_t>(processorArchitectureFilter), "Criteria.ArchitectureFilter"),
+                        TraceLoggingInt32(static_cast<std::int32_t>(candidateArchitecture), "Architecture"),
+                        TraceLoggingHexInt32(static_cast<std::int32_t>(supportedArchitectures), "SupportedArchitectures"),
+                        TraceLoggingUInt16(static_cast<std::uint32_t>(nativeMachine), "NativeMachineArchitecture"),
+                        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+                        TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
                    continue;
                }
            }
@ -228,7 +252,16 @@ winrt::hstring Microsoft::Windows::ApplicationModel::PackageDeploymentResolver::
            {
                if (!IsArchitectureInArchitectures(candidateArchitecture, processorArchitectureFilter))
                {
-                    // package arch doesn't match from specified arch list
+                    TraceLoggingWrite(
+                        PackageManagementTelemetryProvider::Provider(),
+                        "PackageDeployment.Resolver.Scan.NoMatch.Architecture",
+                        TraceLoggingWideString(candidateFullName.c_str(), "PackageFullName"),
+                        TraceLoggingWideString(packageFamilyName.c_str(), "Criteria.PackageFamilyName"),
+                        TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+                        TraceLoggingHexInt32(static_cast<std::int32_t>(processorArchitectureFilter), "Criteria.ArchitectureFilter"),
+                        TraceLoggingInt32(static_cast<std::int32_t>(candidateArchitecture), "Architecture"),
+                        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+                        TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
                    continue;
                }
            }
@ -238,16 +271,30 @@ winrt::hstring Microsoft::Windows::ApplicationModel::PackageDeploymentResolver::
            auto status{ candidate.Status() };
            if (!status.VerifyIsOK())
            {
-                Common::Logging::DebugLog(std::format(L"PackageDeploymentResolver: {} not applicable. Status not OK ({})",
-                                                        candidateFullName.c_str(), criteria.get()));
+                TraceLoggingWrite(
+                    PackageManagementTelemetryProvider::Provider(),
+                    "PackageDeployment.Resolver.Scan.NoMatch.Status",
+                    TraceLoggingWideString(candidateFullName.c_str(), "PackageFullName"),
+                    TraceLoggingWideString(packageFamilyName.c_str(), "Criteria.PackageFamilyName"),
+                    TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+                    TraceLoggingHexInt32(static_cast<std::int32_t>(processorArchitectureFilter), "Criteria.ArchitectureFilter"),
+                    TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+                    TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
                continue;
            }

            // Are we looking for any match?
            if (stopOnFirstMatch)
            {
-                Common::Logging::DebugLog(std::format(L"PackageDeploymentResolver: Stopping on 1st match {} ({})",
-                                 candidateFullName.c_str(), criteria.get()));
+                TraceLoggingWrite(
+                    PackageManagementTelemetryProvider::Provider(),
+                    "PackageDeployment.Resolver.Found.StopOnFirst",
+                    TraceLoggingWideString(candidateFullName.c_str(), "PackageFullName"),
+                    TraceLoggingWideString(packageFamilyName.c_str(), "Criteria.PackageFamilyName"),
+                    TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+                    TraceLoggingHexInt32(static_cast<std::int32_t>(processorArchitectureFilter), "Criteria.ArchitectureFilter"),
+                    TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+                    TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
                return candidateFullName;
            }

@ -260,13 +307,26 @@ winrt::hstring Microsoft::Windows::ApplicationModel::PackageDeploymentResolver::
    // Did we find what we're looking for?
    if (bestFitPackageFullName.empty())
    {
-        Common::Logging::DebugLog(std::format(L"PackageDeploymentResolver: No match ({})",
-                         criteria.get()));
+        TraceLoggingWrite(
+            PackageManagementTelemetryProvider::Provider(),
+            "PackageDeployment.Resolver.NotFound",
+            TraceLoggingWideString(packageFamilyName.c_str(), "Criteria.PackageFamilyName"),
+            TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+            TraceLoggingHexInt32(static_cast<std::int32_t>(processorArchitectureFilter), "Criteria.ArchitectureFilter"),
+            TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+            TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
    }
    else
    {
-        Common::Logging::DebugLog(std::format(L"PackageDeploymentResolver: {} is applicable ({})",
-                         bestFitPackageFullName.c_str(), criteria.get()));
+        TraceLoggingWrite(
+            PackageManagementTelemetryProvider::Provider(),
+            "PackageDeployment.Resolver.Found",
+            TraceLoggingWideString(bestFitPackageFullName.c_str(), "PackageFullName"),
+            TraceLoggingWideString(packageFamilyName.c_str(), "Criteria.PackageFamilyName"),
+            TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+            TraceLoggingHexInt32(static_cast<std::int32_t>(processorArchitectureFilter), "Criteria.ArchitectureFilter"),
+            TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+            TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
    }
    return bestFitPackageFullName;
 }
--- a/dev/PackageManager/API/PackageManager.vcxitems
+++ b/dev/PackageManager/API/PackageManager.vcxitems
@ -45,6 +45,7 @@
    <ClInclude Include="$(MSBuildThisFileDirectory)M.W.M.D.RegisterPackageOptions.h" />
    <ClInclude Include="$(MSBuildThisFileDirectory)M.W.M.D.RemovePackageOptions.h" />
    <ClInclude Include="$(MSBuildThisFileDirectory)M.W.M.D.StagePackageOptions.h" />
+    <ClInclude Include="$(MSBuildThisFileDirectory)MsixPackageManager.h" />
    <ClInclude Include="$(MSBuildThisFileDirectory)PackageDeploymentResolver.h" />
  </ItemGroup>
  <ItemGroup>
@ -52,5 +53,7 @@
      <AdditionalIncludeDirectories>%(AdditionalIncludeDirectories);$(RepoRoot)\dev\DynamicDependency\API;%(OutDir)</AdditionalIncludeDirectories>
    </Midl>
  </ItemGroup>
- 
+  <ItemGroup>
+    <PublicHeaders Include="$(MSBuildThisFileDirectory)MsixPackageManager.h" />
+  </ItemGroup>
 </Project>
--- a/dev/PackageManager/API/PackageManager.vcxitems.filters
+++ b/dev/PackageManager/API/PackageManager.vcxitems.filters
@ -97,6 +97,9 @@
    <ClInclude Include="$(MSBuildThisFileDirectory)M.W.M.D.StagePackageOptions.h">
      <Filter>Header Files</Filter>
    </ClInclude>
+    <ClInclude Include="$(MSBuildThisFileDirectory)MsixPackageManager.h">
+      <Filter>Header Files</Filter>
+    </ClInclude>
    <ClInclude Include="$(MSBuildThisFileDirectory)PackageDeploymentResolver.h">
      <Filter>Header Files</Filter>
    </ClInclude>
--- a/dev/PackageManager/API/pch.h
+++ b/dev/PackageManager/API/pch.h
@ -28,4 +28,5 @@

 #include <appmodel.identity.h>
 #include <appmodel.package.h>
-#include "Logging.h"
+
+#include "MsixPackageManager.h"
--- a/dev/WindowsAppRuntime_BootstrapDLL/MddBootstrap.cpp
+++ b/dev/WindowsAppRuntime_BootstrapDLL/MddBootstrap.cpp
@ -743,7 +743,7 @@ CLSID FindDDLMViaAppExtension(
    PACKAGE_VERSION minVersion)
 {
    // Find the best fit
-    bool foundAny{};
+    // NOTE: DDLM packages ALWAYS have a version > 0.0.0.0 so we can use version=0 as a proxy for 'no match found (so far)'
    PACKAGE_VERSION bestFitVersion{};
    CLSID bestFitClsid{};

@ -809,15 +809,6 @@ CLSID FindDDLMViaAppExtension(
            continue;
        }

-        // Do we have a package under consideration?
-        if (!foundAny)
-        {
-            bestFitVersion = version;
-            bestFitClsid = GetClsid(appExtension);
-            foundAny = true;
-            continue;
-        }
-
        // Do we already have a higher version under consideration?
        if (bestFitVersion.Version < version.Version)
        {
@ -826,7 +817,8 @@ CLSID FindDDLMViaAppExtension(
            continue;
        }
    }
-    THROW_HR_IF_MSG(STATEREPOSITORY_E_DEPENDENCY_NOT_RESOLVED, !foundAny, "AppExtension.Name=%ls, Major=%hu, Minor=%hu, Tag=%ls, MinVersion=%hu.%hu.%hu.%hu",
+    THROW_HR_IF_MSG(STATEREPOSITORY_E_DEPENDENCY_NOT_RESOLVED, bestFitVersion.Version == 0,
+                    "AppExtension.Name=%ls, Major=%hu, Minor=%hu, Tag=%ls, MinVersion=%hu.%hu.%hu.%hu",
                    appExtensionName.c_str(), majorVersion, minorVersion, (!versionTag ? L"" : versionTag),
                    minVersion.Major, minVersion.Minor, minVersion.Build, minVersion.Revision);
    return bestFitClsid;
@ -840,7 +832,8 @@ void FindDDLMViaEnumeration(
    std::wstring& ddlmPackageFullName)
 {
    // Find the best fit
-    PACKAGE_VERSION bestFitVersion{0}; //setting everything to 0
+    // NOTE: DDLM packages ALWAYS have a version > 0.0.0.0 so we can use version=0 as a proxy for 'no match found (so far)'
+    PACKAGE_VERSION bestFitVersion{};
    winrt::hstring bestFitPackageFamilyName{};
    winrt::hstring bestFitPackageFullName{};

@ -886,14 +879,18 @@ void FindDDLMViaEnumeration(
        expectedPublisherId = g_test_ddlmPackagePublisherId.c_str();
    }

-    auto criteria{ wil::str_printf<wil::unique_cotaskmem_string>(L"Major.Minor=%hu.%hu, Tag=%ls, MinVersion=%hu.%hu.%hu.%hu",
-                                                                 majorVersion, minorVersion, (!versionTag ? L"" : versionTag),
-                                                                 minVersion.Major, minVersion.Minor, minVersion.Build, minVersion.Revision) };
-
    winrt::Windows::Management::Deployment::PackageManager packageManager;
    winrt::hstring currentUser;
    const auto c_packageTypes{ winrt::Windows::Management::Deployment::PackageTypes::Main };
    auto packages{ packageManager.FindPackagesForUserWithPackageTypes(currentUser, c_packageTypes) };
+    TraceLoggingWrite(
+        WindowsAppRuntimeBootstrap_TraceLogger::Provider(),
+        "Bootstrap.Initialize.DDLM.Scan",
+        TraceLoggingHexUInt32(majorMinorVersion, "Criteria.MajorMinorVersion"),
+        TraceLoggingWideString(!versionTag ? L"" : versionTag, "Criteria.VersionTag"),
+        TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+        TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
    int packagesScanned{};
    for (auto package : packages)
    {
@ -980,6 +977,15 @@ void FindDDLMViaEnumeration(
        version.Revision = packageVersion.Revision;
        if (version.Version < minVersion.Version)
        {
+            TraceLoggingWrite(
+                WindowsAppRuntimeBootstrap_TraceLogger::Provider(),
+                "Bootstrap.Initialize.DDLM.Scan.NoMatch.Version",
+                TraceLoggingWideString(packageFullName.c_str(), "PackageFullName"),
+                TraceLoggingHexUInt32(majorMinorVersion, "Criteria.MajorMinorVersion"),
+                TraceLoggingWideString(!versionTag ? L"" : versionTag, "Criteria.VersionTag"),
+                TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+                TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+                TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
            continue;
        }

@ -988,28 +994,54 @@ void FindDDLMViaEnumeration(
        const auto currentArchitecture{ AppModel::Identity::GetCurrentArchitecture() };
        if (architecture != currentArchitecture)
        {
+            TraceLoggingWrite(
+                WindowsAppRuntimeBootstrap_TraceLogger::Provider(),
+                "Bootstrap.Initialize.DDLM.Scan.NoMatch.Architecture",
+                TraceLoggingWideString(packageFullName.c_str(), "PackageFullName"),
+                TraceLoggingHexUInt32(majorMinorVersion, "Criteria.MajorMinorVersion"),
+                TraceLoggingWideString(!versionTag ? L"" : versionTag, "Criteria.VersionTag"),
+                TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+                TraceLoggingWideString(::AppModel::Identity::GetCurrentArchitectureAsString(), "CurrentArchitecture"),
+                TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+                TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
            continue;
        }

        // Do we already have a higher version under consideration?
-        // this works for both cases :
-        // 1. find the first package which matches the criteria (because we initiailizue bestfit with 0 version)
-        // 2. find a better match than previously matched best fit
        if (bestFitVersion.Version < version.Version)
        {
+            TraceLoggingWrite(
+                WindowsAppRuntimeBootstrap_TraceLogger::Provider(),
+                "Bootstrap.Initialize.DDLM.Scan.Match",
+                TraceLoggingWideString(packageFullName.c_str(), "PackageFullName"),
+                TraceLoggingHexUInt32(majorMinorVersion, "Criteria.MajorMinorVersion"),
+                TraceLoggingWideString(!versionTag ? L"" : versionTag, "Criteria.VersionTag"),
+                TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+                TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+                TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
            bestFitVersion = version;
            bestFitPackageFamilyName = packageId.FamilyName();
            bestFitPackageFullName = packageId.FullName();
            continue;
        }
    }
-    // if bestFitVersion is 0, the value we initialized it with,  then we didn't find a suitable candidate
-    THROW_HR_IF_MSG(STATEREPOSITORY_E_DEPENDENCY_NOT_RESOLVED, bestFitVersion.Version == 0, "No suitable version matching criteria is found. Criteria: %ls", criteria.get());
-    {
-        wchar_t printmsg[128];
-        Common::Logging::DebugLog(std::format(L"Bootstrap.Intitialize: {} best matches the criteria ({}) of {} packages scanned",
-                                        bestFitPackageFullName.c_str(), criteria.get(), packagesScanned));
-    }
+
+    THROW_HR_IF_MSG(STATEREPOSITORY_E_DEPENDENCY_NOT_RESOLVED, bestFitVersion.Version == 0,
+                    "Major.Minor=%hu.%hu, Tag=%ls, MinVersion=%hu.%hu.%hu.%hu",
+                    majorVersion, minorVersion, (!versionTag ? L"" : versionTag),
+                    minVersion.Major, minVersion.Minor, minVersion.Build, minVersion.Revision);
+
+    // Success!
+    TraceLoggingWrite(
+        WindowsAppRuntimeBootstrap_TraceLogger::Provider(),
+        "Bootstrap.Initialize.DDLM.Found",
+        TraceLoggingWideString(bestFitPackageFullName.c_str(), "PackageFullName"),
+        TraceLoggingHexUInt32(majorMinorVersion, "Criteria.MajorMinorVersion"),
+        TraceLoggingWideString(!versionTag ? L"" : versionTag, "Criteria.VersionTag"),
+        TraceLoggingHexUInt64(minVersion.Version, "Criteria.MinVersion"),
+        TraceLoggingInt32(packagesScanned, "PackagesScanned"),
+        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
+        TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
    ddlmPackageFamilyName = bestFitPackageFamilyName.c_str();
    ddlmPackageFullName = bestFitPackageFullName.c_str();
 }
@ -1081,7 +1113,7 @@ HRESULT MddBootstrapInitialize_Log(
        const auto versionTagLength{ wcslen(versionTag) };
        if (versionTagLength > ARRAYSIZE(formattedVersionTag) - 1)
        {
-            (void)LOG_HR(E_INVALIDARG, "MddBootstrapInitialize: VersionTag invalid (too long): %ls", versionTag);
+            (void)LOG_HR_MSG(E_INVALIDARG, "MddBootstrapInitialize: VersionTag invalid (too long): %ls", versionTag);
            versionTag = L"***InvalidVersionTag***";
        }
        FAIL_FAST_IF_FAILED(StringCchPrintfW(formattedVersionTag, ARRAYSIZE(formattedVersionTag), L"-%s", versionTag));
--- a/dev/WindowsAppRuntime_BootstrapDLL/pch.h
+++ b/dev/WindowsAppRuntime_BootstrapDLL/pch.h
@ -16,6 +16,5 @@
 #include "framework.h"
 #include "MddBootstrapActivity.h"
 #include "MddBootstrapTracelogging.h"
-#include "logging.h"

 #endif //PCH_H
--- a/docs/Coding-Guidelines.md
+++ b/docs/Coding-Guidelines.md
@ -12,6 +12,7 @@ languages used in implementation or testing.
 - Git
  - [Checkin-to-main/develop Policy](Coding-Guidelines/GitCheckinToMainPolicy.md)
  - [Branches: main vs develop](Coding-Guidelines/develop-branch.md)
+- [Error Handling and Logging](Coding-Guidelines/ErrorHandlingAndLogging.md)
 - [Experimental](Coding-Guidelines/Experimental.md)-only features
  - Use [TerminalVelocity](Coding-Guidelines/TerminalVelocity.md) tag and disable features
 - [Hybrid CRT](Coding-Guidelines/HybridCRT.md)
--- a/docs/Coding-Guidelines/ErrorHandlingAndLogging.md
+++ b/docs/Coding-Guidelines/ErrorHandlingAndLogging.md
@ -0,0 +1,35 @@
+# Error Handling and Logging
+
+# Error Handling
+
+<span style="color:green">**DO**</span> Throw exceptions to report exceptional failures.
+
+<span style="color:green">**DO**</span> Use
+[WIL error handling helpers](https://github.com/Microsoft/wil/wiki/Error-handling-helpers) when
+handling error code failures (`THROW_*()`, `RETURN_*()`, `FAIL_FAST_*()`, `LOG_*()`).
+
+## Errors
+
+<span style="color:green">**DO**</span> Use existing 'HRESULT's if you can. Be careful to pick an
+existing HRESULT whose symbolic name and message convey the intent and don't mislead the developer,
+administrator or user.
+
+<span style="color:green">**DO**</span> Create new `HRESULT`s with `FACILITY_ITF` only if you can't
+find a reasonable existing one. Any new `FACILITY_ITF` error MUST use code values in the range
+0x0200-0xFFFF. See
+[Codes in FACILITY_ITF](https://learn.microsoft.com/windows/win32/com/codes-in-facility-itf) for
+more details.
+
+# Logging
+
+<span style="color:green">**DO**</span> Rely on
+[WIL error handling helpers](https://github.com/Microsoft/wil/wiki/Error-handling-helpers) to log
+failures.
+
+<span style="color:green">**DO**</span> Use `TraceLoggingWrite()` to log non-failure information.
+
+<span style="color:red">**DON'T**</span> Use WIL's `LOG_HR()` to report non-failure information.
+`LOG_HR()` will FAIL_FAST if handled a `SUCCEEDED(hr)`.
+
+<span style="color:red">**DON'T**</span> Define error `HRESULTS` to pass to `LOG_HR()` to report
+non-failure information. Non-error information should be reported via `TraceLoggingWrite()`.