Add ODS logger and use it during init (#4969)

## Change The user settings (and then group policy) initialization happen before we get the file logger set up. To be able to see into what is happening there more easily, this change creates a logger that uses `OutputDebugString` and uses it during the initial file logger creation.
microsoft · Nov 20, 2024 · 25ccc2a · 25ccc2a
1 parent 03df824
commit 25ccc2a
Show file tree

Hide file tree

Showing 6 changed files with 131 additions and 8 deletions.
diff --git a/src/AppInstallerCLICore/COMContext.cpp b/src/AppInstallerCLICore/COMContext.cpp
@@ -4,6 +4,7 @@
 #include "COMContext.h"
 #include <AppInstallerFileLogger.h>
 #include <winget/TraceLogger.h>
+#include <winget/OutputDebugStringLogger.h>
 
 namespace AppInstaller::CLI::Execution
 {
@@ -77,12 +78,19 @@ namespace AppInstaller::CLI::Execution
 
     void COMContext::SetLoggers(std::optional<AppInstaller::Logging::Channel> channel, std::optional<AppInstaller::Logging::Level> level)
     {
+        // Set up debug string logging during initialization
+        Logging::OutputDebugStringLogger::Add();
+        Logging::Log().EnableChannel(Logging::Channel::All);
+        Logging::Log().SetLevel(Logging::Level::Verbose);
+
         Logging::Log().EnableChannel(channel.has_value() ? channel.value() : Settings::User().Get<Settings::Setting::LoggingChannelPreference>());
         Logging::Log().SetLevel(level.has_value() ? level.value() : Settings::User().Get<Settings::Setting::LoggingLevelPreference>());
 
         // TODO: Log to file for COM API calls only when debugging in visual studio
         Logging::FileLogger::Add(s_comLogFileNamePrefix);
 
+        Logging::OutputDebugStringLogger::Remove();
+
 #ifndef AICLI_DISABLE_TEST_HOOKS
         if (!Settings::User().Get<Settings::Setting::KeepAllLogFiles>())
 #endif

diff --git a/src/AppInstallerCLICore/Core.cpp b/src/AppInstallerCLICore/Core.cpp
@@ -9,6 +9,7 @@
 #include "Commands/InstallCommand.h"
 #include "COMContext.h"
 #include <AppInstallerFileLogger.h>
+#include <winget/OutputDebugStringLogger.h>
 
 #ifndef AICLI_DISABLE_TEST_HOOKS
 #include <winget/Debugging.h>
@@ -66,21 +67,34 @@ namespace AppInstaller::CLI
 
         init_apartment();
 
-#ifndef AICLI_DISABLE_TEST_HOOKS
+#ifndef AICLI_DISABLE_TEST_HOOKS
+        // We have to do this here so the auto minidump config initialization gets caught
+        Logging::OutputDebugStringLogger::Add();
+        Logging::Log().EnableChannel(Logging::Channel::All);
+        Logging::Log().SetLevel(Logging::Level::Verbose);
+
         if (Settings::User().Get<Settings::Setting::EnableSelfInitiatedMinidump>())
         {
             Debugging::EnableSelfInitiatedMinidump();
-        }
+        }
+
+        Logging::OutputDebugStringLogger::Remove();
 #endif
 
         Logging::UseGlobalTelemetryLoggerActivityIdOnly();
 
         Execution::Context context{ std::cout, std::cin };
-        auto previousThreadGlobals = context.SetForCurrentThread();
+        auto previousThreadGlobals = context.SetForCurrentThread();
+
+        // Set up debug string logging during initialization
+        Logging::OutputDebugStringLogger::Add();
+        Logging::Log().EnableChannel(Logging::Channel::All);
+        Logging::Log().SetLevel(Logging::Level::Verbose);
 
         Logging::Log().EnableChannel(Settings::User().Get<Settings::Setting::LoggingChannelPreference>());
         Logging::Log().SetLevel(Settings::User().Get<Settings::Setting::LoggingLevelPreference>());
-        Logging::FileLogger::Add();
+        Logging::FileLogger::Add();
+        Logging::OutputDebugStringLogger::Remove();
         Logging::EnableWilFailureTelemetry();
 
         // Set output to UTF8
@@ -171,23 +185,37 @@ namespace AppInstaller::CLI
 
     void ServerInitialize()
     {
-#ifndef AICLI_DISABLE_TEST_HOOKS
+#ifndef AICLI_DISABLE_TEST_HOOKS
+        // We have to do this here so the auto minidump config initialization gets caught
+        Logging::OutputDebugStringLogger::Add();
+        Logging::Log().EnableChannel(Logging::Channel::All);
+        Logging::Log().SetLevel(Logging::Level::Verbose);
+
         if (Settings::User().Get<Settings::Setting::EnableSelfInitiatedMinidump>())
         {
             Debugging::EnableSelfInitiatedMinidump();
-        }
+        }
+
+        Logging::OutputDebugStringLogger::Remove();
 #endif
 
         AppInstaller::CLI::Execution::COMContext::SetLoggers();
     }
 
     void InProcInitialize()
     {
-#ifndef AICLI_DISABLE_TEST_HOOKS
+#ifndef AICLI_DISABLE_TEST_HOOKS
+        // We have to do this here so the auto minidump config initialization gets caught
+        Logging::OutputDebugStringLogger::Add();
+        Logging::Log().EnableChannel(Logging::Channel::All);
+        Logging::Log().SetLevel(Logging::Level::Verbose);
+
         if (Settings::User().Get<Settings::Setting::EnableSelfInitiatedMinidump>())
         {
             Debugging::EnableSelfInitiatedMinidump();
-        }
+        }
+
+        Logging::OutputDebugStringLogger::Remove();
 #endif
 
         // Explicitly set default channel and level before user settings from PackageManagerSettings

diff --git a/src/AppInstallerCommonCore/AppInstallerCommonCore.vcxproj b/src/AppInstallerCommonCore/AppInstallerCommonCore.vcxproj
@@ -448,6 +448,7 @@
     </ClInclude>
     <ClInclude Include="Public\winget\NameNormalization.h" />
     <ClInclude Include="Public\winget\NetworkSettings.h" />
+    <ClInclude Include="Public\winget\OutputDebugStringLogger.h" />
     <ClInclude Include="Public\winget\PackageDependenciesValidationUtil.h" />
     <ClInclude Include="Public\winget\PackageVersionDataManifest.h" />
     <ClInclude Include="Public\winget\Pin.h" />
@@ -504,6 +505,7 @@
     </ClCompile>
     <ClCompile Include="NameNormalization.cpp" />
     <ClCompile Include="NetworkSettings.cpp" />
+    <ClCompile Include="OutputDebugStringLogger.cpp" />
     <ClCompile Include="PackageDependenciesValidationUtil.cpp" />
     <ClCompile Include="PackageVersionDataManifest.cpp" />
     <ClCompile Include="Pin.cpp" />

diff --git a/src/AppInstallerCommonCore/AppInstallerCommonCore.vcxproj.filters b/src/AppInstallerCommonCore/AppInstallerCommonCore.vcxproj.filters
@@ -207,6 +207,9 @@
     <ClInclude Include="Public\winget\Fonts.h">
       <Filter>Public\winget</Filter>
     </ClInclude>
+    <ClInclude Include="Public\winget\OutputDebugStringLogger.h">
+      <Filter>Public\winget</Filter>
+    </ClInclude>
   </ItemGroup>
   <ItemGroup>
     <ClCompile Include="pch.cpp">
@@ -374,6 +377,9 @@
     <ClCompile Include="Fonts.cpp">
       <Filter>Source Files</Filter>
     </ClCompile>
+    <ClCompile Include="OutputDebugStringLogger.cpp">
+      <Filter>Source Files</Filter>
+    </ClCompile>
   </ItemGroup>
   <ItemGroup>
     <None Include="PropertySheet.props" />

diff --git a/src/AppInstallerCommonCore/OutputDebugStringLogger.cpp b/src/AppInstallerCommonCore/OutputDebugStringLogger.cpp
@@ -0,0 +1,50 @@
+// Copyright (c) Microsoft Corporation.
+// Licensed under the MIT License.
+#include "pch.h"
+#include "winget/OutputDebugStringLogger.h"
+
+namespace AppInstaller::Logging
+{
+    namespace
+    {
+        static constexpr std::string_view s_OutputDebugStringLoggerName = "OutputDebugStringLogger";
+    }
+
+    std::string OutputDebugStringLogger::GetName() const
+    {
+        return std::string{ s_OutputDebugStringLoggerName };
+    }
+
+    void OutputDebugStringLogger::Write(Channel channel, Level, std::string_view message) noexcept try
+    {
+        std::stringstream strstr;
+        strstr << "[" << std::setw(GetMaxChannelNameLength()) << std::left << std::setfill(' ') << GetChannelName(channel) << "] " << message << std::endl;
+        std::string formattedMessage = std::move(strstr).str();
+
+        OutputDebugStringA(formattedMessage.c_str());
+    }
+    catch (...)
+    {
+        // Just eat any exceptions here; better than losing logs
+    }
+
+    void OutputDebugStringLogger::WriteDirect(Channel, Level, std::string_view message) noexcept try
+    {
+        std::string nullTerminatedMessage{ message };
+        OutputDebugStringA(nullTerminatedMessage.c_str());
+    }
+    catch (...)
+    {
+        // Just eat any exceptions here; better than losing logs
+    }
+
+    void OutputDebugStringLogger::Add()
+    {
+        Log().AddLogger(std::make_unique<OutputDebugStringLogger>());
+    }
+
+    void OutputDebugStringLogger::Remove()
+    {
+        Log().RemoveLogger(std::string{ s_OutputDebugStringLoggerName });
+    }
+}
diff --git a/src/AppInstallerCommonCore/Public/winget/OutputDebugStringLogger.h b/src/AppInstallerCommonCore/Public/winget/OutputDebugStringLogger.h
@@ -0,0 +1,29 @@
+// Copyright (c) Microsoft Corporation.
+// Licensed under the MIT License.
+#pragma once
+#include <AppInstallerLogging.h>
+
+namespace AppInstaller::Logging
+{
+    // Sends logs to the OutputDebugString function.
+    // Intended for use during initialization debugging.
+    struct OutputDebugStringLogger : ILogger
+    {
+        OutputDebugStringLogger() = default;
+
+        ~OutputDebugStringLogger() = default;
+
+        // ILogger
+        std::string GetName() const override;
+
+        void Write(Channel channel, Level, std::string_view message) noexcept override;
+
+        void WriteDirect(Channel channel, Level level, std::string_view message) noexcept override;
+
+        // Adds OutputDebugStringLogger to the current Log
+        static void Add();
+
+        // Removes OutputDebugStringLogger from the current Log
+        static void Remove();
+    };
+}