Fix logging of large REST response (#1489)

src/AppInstallerCommonCore/AppInstallerLogging.cpp

@@ -125,6 +125,19 @@ namespace AppInstaller::Logging
         }
     }
 
+    void DiagnosticLogger::WriteDirect(Channel channel, Level level, std::string_view message)
+    {
+        THROW_HR_IF_MSG(E_INVALIDARG, channel == Channel::All, "Cannot write to all channels");
+
+        if (IsEnabled(channel, level))
+        {
+            for (auto& logger : m_loggers)
+            {
+                logger->WriteDirect(message);
+            }
+        }
+    }
+
     DiagnosticLogger& Log()
     {
         ThreadLocalStorage::ThreadGlobals* pThreadGlobals = ThreadLocalStorage::ThreadGlobals::GetForCurrentThread();

src/AppInstallerCommonCore/FileLogger.cpp

@@ -73,6 +73,15 @@ namespace AppInstaller::Logging
         // Just eat any exceptions here; better than losing logs
     }
 
+    void FileLogger::WriteDirect(std::string_view message) noexcept try
+    {
+        m_stream << message << std::endl;
+    }
+    catch (...)
+    {
+        // Just eat any exceptions here; better than losing logs
+    }
+
     void FileLogger::BeginCleanup(const std::filesystem::path& filePath)
     {
         std::thread([filePath]()

src/AppInstallerCommonCore/Manifest/ManifestValidation.cpp

@@ -1,6 +1,7 @@
 // Copyright (c) Microsoft Corporation.
 // Licensed under the MIT License.
 #include "pch.h"
+#include "AppInstallerLogging.h"
 #include "winget/ManifestValidation.h"
 #include "winget/Locale.h"
 
@@ -72,6 +73,10 @@ namespace AppInstaller::Manifest
 
             if (!duplicateInstallerFound && !installerSet.insert(installer).second)
             {
+                AICLI_LOG(Core, Error, << "Duplicate installer: Type[" << InstallerTypeToString(installer.InstallerType) <<
+                    "] Architecture[" << Utility::ToString(installer.Arch) << "] Locale[" << installer.Locale <<
+                    "] Scope[" << ScopeToString(installer.Scope) << "]");
+
                 resultErrors.emplace_back(ManifestError::DuplicateInstallerEntry);
                 duplicateInstallerFound = true;
             }

src/AppInstallerCommonCore/Public/AppInstallerFileLogger.h

@@ -35,6 +35,8 @@ namespace AppInstaller::Logging
 
         void Write(Channel channel, Level level, std::string_view message) noexcept override;
 
+        void WriteDirect(std::string_view message) noexcept override;
+
         // Starts a background task to clean up old log files.
         static void BeginCleanup(const std::filesystem::path& filePath);
 

src/AppInstallerCommonCore/Public/AppInstallerLogging.h

@@ -23,6 +23,22 @@
         } \
     } while (0, 0)
 
+// Consider using this macro when the string might be larger than 4K.
+// The normal macro has some buffering that occurs; it can cut off larger strings and is slower.
+#define AICLI_LOG_LARGE_STRING(_channel_,_level_,_headerStream_,_largeString_) \
+    do { \
+        auto _aicli_log_channel = AppInstaller::Logging::Channel:: _channel_; \
+        auto _aicli_log_level = AppInstaller::Logging::Level:: _level_; \
+        auto& _aicli_log_log = AppInstaller::Logging::Log(); \
+        if (_aicli_log_log.IsEnabled(_aicli_log_channel, _aicli_log_level)) \
+        { \
+            AppInstaller::Logging::LoggingStream _aicli_log_strstr; \
+            _aicli_log_strstr _headerStream_; \
+            _aicli_log_log.Write(_aicli_log_channel, _aicli_log_level, _aicli_log_strstr.str()); \
+            _aicli_log_log.WriteDirect(_aicli_log_channel, _aicli_log_level, _largeString_); \
+        } \
+    } while (0, 0)
+
 namespace AppInstaller::Logging
 {
     // The channel that the log is from.
@@ -65,6 +81,9 @@ namespace AppInstaller::Logging
 
         // Informs the logger of the given log.
         virtual void Write(Channel channel, Level level, std::string_view message) noexcept = 0;
+
+        // Informs the logger of the given log with the intention that no buffering occurs (in winget code).
+        virtual void WriteDirect(std::string_view message) noexcept = 0;
     };
 
     // This type contains the set of loggers that diagnostic logging will be sent to.
@@ -120,6 +139,10 @@ namespace AppInstaller::Logging
         // Writes a log line, if the given channel and level are enabled.
         void Write(Channel channel, Level level, std::string_view message);
 
+        // Writes a log line, if the given channel and level are enabled.
+        // Use to make large logs more efficient by writing directly to the output streams.
+        void WriteDirect(Channel channel, Level level, std::string_view message);
+
     private:
 
         std::vector<std::unique_ptr<ILogger>> m_loggers;

src/AppInstallerCommonCore/Public/winget/TraceLogger.h

@@ -19,6 +19,9 @@ namespace AppInstaller::Logging
 
         // ILogger
         std::string GetName() const override;
+
         void Write(Channel channel, Level, std::string_view message) noexcept override;
+
+        void WriteDirect(std::string_view message) noexcept override;
     };
 }

src/AppInstallerCommonCore/TraceLogger.cpp

@@ -24,6 +24,19 @@ namespace AppInstaller::Logging
         // Just eat any exceptions here; better to lose logs than functionality
     }
 
+    void TraceLogger::WriteDirect(std::string_view message) noexcept try
+    {
+        TraceLoggingWriteActivity(g_hTraceProvider,
+            "Diagnostics",
+            nullptr, // TODO: ActivityId of the Global and COMContext telemetry to be logged in future
+            nullptr,
+            TraceLoggingCountedUtf8String(message.data(), static_cast<ULONG>(message.size()), "LogMessage"));
+    }
+    catch (...)
+    {
+        // Just eat any exceptions here; better to lose logs than functionality
+    }
+
     std::string TraceLogger::GetName() const
     {
         return "Trace";

src/AppInstallerRepositoryCore/Rest/Schema/HttpClientHelper.cpp

@@ -86,7 +86,9 @@ namespace AppInstaller::Repository::Rest::Schema
     std::optional<web::json::value> HttpClientHelper::ValidateAndExtractResponse(const web::http::http_response& response) const
     {
         AICLI_LOG(Repo, Info, << "Response status: " << response.status_code());
-        AICLI_LOG(Repo, Verbose, << "Response details: " << utility::conversions::to_utf8string(response.to_string()));
+        // Ensure that we wait for the content to be ready before we log it; otherwise it will be truncated.
+        AICLI_LOG_LARGE_STRING(Repo, Verbose, << "Response details:",
+            response.content_ready().then([&](const web::http::http_response&) { return utility::conversions::to_utf8string(response.to_string()); }).get());
 
         std::optional<web::json::value> result;
         switch (response.status_code())