diagnostics: improve logging of hcs helper utilities on debug builds

.gitignore

@@ -65,4 +65,5 @@ package/x64
 /appx-logs.txt
 tools/clang-format.exe
 /linux-crashes
-doc/site/
+doc/site/
+_codeql_detected_source_root

src/windows/common/hcs.cpp

@@ -78,6 +78,8 @@ wsl::windows::common::hcs::unique_hcs_operation wsl::windows::common::hcs::Creat
 
 wsl::windows::common::hcs::unique_hcs_system wsl::windows::common::hcs::CreateComputeSystem(_In_ PCWSTR Id, _In_ PCWSTR Configuration)
 {
+    WSL_LOG_DEBUG("HcsCreateComputeSystem", TraceLoggingValue(Id, "id"), TraceLoggingValue(Configuration, "configuration"));
+
     ExecutionContext context(Context::HCS);
 
     const unique_hcs_operation operation = CreateOperation();
@@ -98,32 +100,39 @@ wsl::windows::common::hcs::unique_hcs_system wsl::windows::common::hcs::CreateCo
 
 std::vector<std::string> wsl::windows::common::hcs::GetProcessorFeatures()
 {
-    ExecutionContext context(Context::HCS);
+    static std::vector<std::string> g_processorFeatures;
+    static std::once_flag flag;
+    std::call_once(flag, [&]() {
+        ExecutionContext context(Context::HCS);
 
-    wil::unique_cotaskmem_string result;
-    THROW_IF_FAILED(::HcsGetServiceProperties(c_processorCapabilitiesQuery, &result));
+        wil::unique_cotaskmem_string result;
+        THROW_IF_FAILED(::HcsGetServiceProperties(c_processorCapabilitiesQuery, &result));
 
-    const auto properties = wsl::shared::FromJson<ServicePropertiesResponse<PropertyResponse<ProcessorCapabilitiesInfo>>>(result.get());
+        const auto properties =
+            wsl::shared::FromJson<ServicePropertiesResponse<PropertyResponse<ProcessorCapabilitiesInfo>>>(result.get());
 
-    const auto& response = properties.PropertyResponses.at(c_processorCapabilities);
-    if (response.Error)
-    {
-        THROW_HR_MSG(static_cast<HRESULT>(response.Error->Error), "%hs", response.Error->ErrorMessage.c_str());
-    }
+        const auto& response = properties.PropertyResponses.at(c_processorCapabilities);
+        if (response.Error)
+        {
+            THROW_HR_MSG(static_cast<HRESULT>(response.Error->Error), "%hs", response.Error->ErrorMessage.c_str());
+        }
+
+        g_processorFeatures = std::move(response.Response.ProcessorFeatures);
+    });
 
-    return response.Response.ProcessorFeatures;
+    return g_processorFeatures;
 }
 
 wsl::shared::hns::HNSEndpoint wsl::windows::common::hcs::GetEndpointProperties(HCN_ENDPOINT Endpoint)
 {
+    WSL_LOG_DEBUG("HcsGetEndpointProperties");
+
+    ExecutionContext context(Context::HNS);
+
     wil::unique_cotaskmem_string propertiesString;
     wil::unique_cotaskmem_string error;
-
-    {
-        ExecutionContext context(Context::HNS);
-        const auto result = HcnQueryEndpointProperties(Endpoint, nullptr, &propertiesString, &error);
-        THROW_IF_FAILED_MSG(result, "HcnQueryEndpointProperties %ls", error.get());
-    }
+    const auto result = HcnQueryEndpointProperties(Endpoint, nullptr, &propertiesString, &error);
+    THROW_IF_FAILED_MSG(result, "HcnQueryEndpointProperties %ls", error.get());
 
     return wsl::shared::FromJson<wsl::shared::hns::HNSEndpoint>(propertiesString.get());
 }
@@ -147,66 +156,84 @@ GUID wsl::windows::common::hcs::GetRuntimeId(_In_ HCS_SYSTEM ComputeSystem)
 
 std::pair<uint32_t, uint32_t> wsl::windows::common::hcs::GetSchemaVersion()
 {
-    PropertyQuery query;
-    query.PropertyTypes.emplace_back(PropertyType::Basic);
-
-    ExecutionContext context(Context::HCS);
-    wil::unique_cotaskmem_string result;
-
-    THROW_IF_FAILED(::HcsGetServiceProperties(wsl::shared::ToJsonW(query).c_str(), &result));
-
-    const auto properties = wsl::shared::FromJson<ServiceProperties<BasicInformation>>(result.get());
-    THROW_HR_IF_MSG(E_UNEXPECTED, properties.Properties.empty(), "%ls", result.get());
-
-    uint32_t majorVersion = 0;
-    uint32_t minorVersion = 0;
-    for (const auto& version : properties.Properties[0].SupportedSchemaVersions)
-    {
-        if (version.Major >= majorVersion)
+    static std::pair<uint32_t, uint32_t> g_schemaVersion{};
+    static std::once_flag flag;
+    std::call_once(flag, [&]() {
+        ExecutionContext context(Context::HCS);
+
+        PropertyQuery query;
+        query.PropertyTypes.emplace_back(PropertyType::Basic);
+        wil::unique_cotaskmem_string result;
+        THROW_IF_FAILED(::HcsGetServiceProperties(wsl::shared::ToJsonW(query).c_str(), &result));
+
+        const auto properties = wsl::shared::FromJson<ServiceProperties<BasicInformation>>(result.get());
+        THROW_HR_IF_MSG(E_UNEXPECTED, properties.Properties.empty(), "%ls", result.get());
+
+        uint32_t majorVersion = 0;
+        uint32_t minorVersion = 0;
+        for (const auto& version : properties.Properties[0].SupportedSchemaVersions)
         {
-            if ((version.Major > majorVersion) || (version.Minor > minorVersion))
+            if (version.Major >= majorVersion)
             {
-                majorVersion = version.Major;
-                minorVersion = version.Minor;
+                if ((version.Major > majorVersion) || (version.Minor > minorVersion))
+                {
+                    majorVersion = version.Major;
+                    minorVersion = version.Minor;
+                }
             }
         }
-    }
 
-    return {majorVersion, minorVersion};
+        g_schemaVersion = {majorVersion, minorVersion};
+    });
+
+    return g_schemaVersion;
 }
 
 void wsl::windows::common::hcs::GrantVmAccess(_In_ PCWSTR VmId, _In_ PCWSTR FilePath)
 {
+    WSL_LOG_DEBUG("HcsGrantVmAccess", TraceLoggingValue(VmId, "vmId"), TraceLoggingValue(FilePath, "filePath"));
+
     ExecutionContext context(Context::HCS);
 
-    THROW_IF_FAILED_MSG(::HcsGrantVmAccess(VmId, FilePath), "Path (%ws)", FilePath);
+    THROW_IF_FAILED_MSG(::HcsGrantVmAccess(VmId, FilePath), "HcsGrantVmAccess(%ls, %ls)", VmId, FilePath);
 }
 
 void wsl::windows::common::hcs::ModifyComputeSystem(_In_ HCS_SYSTEM ComputeSystem, _In_ PCWSTR Configuration, _In_opt_ HANDLE Identity)
 {
+    WSL_LOG_DEBUG("HcsModifyComputeSystem", TraceLoggingValue(Configuration, "configuration"));
+
     ExecutionContext context(Context::HCS);
 
     const unique_hcs_operation operation = CreateOperation();
     THROW_IF_FAILED_MSG(
-        ::HcsModifyComputeSystem(ComputeSystem, operation.get(), Configuration, Identity), "HcsModifyComputeSystem (%ws)", Configuration);
+        ::HcsModifyComputeSystem(ComputeSystem, operation.get(), Configuration, Identity), "HcsModifyComputeSystem (%ls)", Configuration);
 
     wil::unique_cotaskmem_string resultDocument;
     const auto result = ::HcsWaitForOperationResult(operation.get(), INFINITE, &resultDocument);
-    THROW_IF_FAILED_MSG(result, "HcsModifyComputeSystem failed (%ls - error string: %ls)", Configuration, resultDocument.get());
+    if (FAILED(result))
+    {
+        // N.B. Logging is split into two calls because the configuration and error strings can be quite long.
+        LOG_HR_MSG(result, "HcsModifyComputeSystem(%ls)", Configuration);
+        THROW_HR_MSG(result, "HcsModifyComputeSystem failed (error string: %ls)", resultDocument.get());
+    }
 }
 
 wsl::windows::common::hcs::unique_hcs_system wsl::windows::common::hcs::OpenComputeSystem(_In_ PCWSTR Id, _In_ DWORD RequestedAccess)
 {
+    WSL_LOG_DEBUG("HcsOpenComputeSystem", TraceLoggingValue(Id, "id"), TraceLoggingValue(RequestedAccess, "requestedAccess"));
+
     ExecutionContext context(Context::HCS);
 
     unique_hcs_system system;
-    THROW_IF_FAILED(::HcsOpenComputeSystem(Id, RequestedAccess, &system));
+    THROW_IF_FAILED_MSG(::HcsOpenComputeSystem(Id, RequestedAccess, &system), "HcsOpenComputeSystem(%ls)", Id);
 
     return system;
 }
 
 void wsl::windows::common::hcs::RegisterCallback(_In_ HCS_SYSTEM ComputeSystem, _In_ HCS_EVENT_CALLBACK Callback, _In_ void* Context)
 {
+    WSL_LOG_DEBUG("HcsSetComputeSystemCallback");
+
     ExecutionContext context(Context::HCS);
 
     THROW_IF_FAILED(::HcsSetComputeSystemCallback(ComputeSystem, HcsEventOptionNone, Context, Callback));
@@ -222,25 +249,36 @@ void wsl::windows::common::hcs::RemoveScsiDisk(_In_ HCS_SYSTEM ComputeSystem, _I
 
 void wsl::windows::common::hcs::RevokeVmAccess(_In_ PCWSTR VmId, _In_ PCWSTR FilePath)
 {
+    WSL_LOG_DEBUG("HcsRevokeVmAccess", TraceLoggingValue(VmId, "vmId"), TraceLoggingValue(FilePath, "filePath"));
+
     ExecutionContext context(Context::HCS);
 
-    THROW_IF_FAILED(::HcsRevokeVmAccess(VmId, FilePath));
+    THROW_IF_FAILED_MSG(::HcsRevokeVmAccess(VmId, FilePath), "HcsRevokeVmAccess(%ls, %ls)", VmId, FilePath);
 }
 
 void wsl::windows::common::hcs::StartComputeSystem(_In_ HCS_SYSTEM ComputeSystem, _In_ LPCWSTR Configuration)
 {
+    WSL_LOG_DEBUG("HcsStartComputeSystem", TraceLoggingValue(Configuration, "configuration"));
+
     ExecutionContext context(Context::HCS);
 
     const unique_hcs_operation operation = CreateOperation();
     THROW_IF_FAILED(::HcsStartComputeSystem(ComputeSystem, operation.get(), nullptr));
 
     wil::unique_cotaskmem_string resultDocument;
     const auto result = ::HcsWaitForOperationResult(operation.get(), INFINITE, &resultDocument);
-    THROW_IF_FAILED_MSG(result, "HcsStartComputeSystem failed (error string: %ls, configuration: %ls)", resultDocument.get(), Configuration);
+    if (FAILED(result))
+    {
+        // N.B. Logging is split into two calls because the configuration and error strings can be quite long.
+        LOG_HR_MSG(result, "HcsStartComputeSystem(%ls)", Configuration);
+        THROW_HR_MSG(result, "HcsStartComputeSystem failed (error string: %ls)", resultDocument.get());
+    }
 }
 
 void wsl::windows::common::hcs::TerminateComputeSystem(_In_ HCS_SYSTEM ComputeSystem)
 {
+    WSL_LOG_DEBUG("HcsTerminateComputeSystem");
+
     ExecutionContext context(Context::HCS);
 
     const unique_hcs_operation operation = CreateOperation();
@@ -254,6 +292,8 @@ void wsl::windows::common::hcs::TerminateComputeSystem(_In_ HCS_SYSTEM ComputeSy
 wsl::windows::common::hcs::unique_hcn_service_callback wsl::windows::common::hcs::RegisterServiceCallback(
     _In_ HCS_NOTIFICATION_CALLBACK Callback, _In_ PVOID Context)
 {
+    WSL_LOG_DEBUG("HcsRegisterServiceCallback");
+
     ExecutionContext context(Context::HNS);
 
     unique_hcn_service_callback callbackHandle;
@@ -265,6 +305,8 @@ wsl::windows::common::hcs::unique_hcn_service_callback wsl::windows::common::hcs
 wsl::windows::common::hcs::unique_hcn_guest_network_service_callback wsl::windows::common::hcs::RegisterGuestNetworkServiceCallback(
     _In_ const unique_hcn_guest_network_service& GuestNetworkService, _In_ HCS_NOTIFICATION_CALLBACK Callback, _In_ PVOID Context)
 {
+    WSL_LOG_DEBUG("HcsRegisterGuestNetworkServiceCallback");
+
     ExecutionContext context(Context::HNS);
 
     unique_hcn_guest_network_service_callback callbackHandle;