commit 199e60cda177fbfa56f05cdfabaa147bef52087a parent 25be81a978af6ccf6727046764a43313bbcf1e10 Author: sachintaMSFT <80828309+sachintaMSFT@users.noreply.github.com> Date: Tue, 8 Jun 2021 11:26:06 -0700 Enable COM APIs to log diagnostic and telemetry events and Log Corela… (#1006) Diffstat:
20 files changed, 243 insertions(+), 113 deletions(-)
diff --git a/.github/actions/spelling/allow.txt b/.github/actions/spelling/allow.txt @@ -478,6 +478,7 @@ uncomment und undef unicode +UNICODESTRING uninstall uninstalling Unregister diff --git a/.github/actions/spelling/expect.txt b/.github/actions/spelling/expect.txt @@ -288,6 +288,7 @@ temppath testexampleinstaller thiscouldbeapc threehundred +Tlg tombstoned tpl transitioning diff --git a/src/AppInstallerCLICore/COMContext.cpp b/src/AppInstallerCLICore/COMContext.cpp @@ -5,6 +5,7 @@ namespace AppInstaller { + static constexpr std::string_view s_comLogFileNamePrefix = "WPM"sv; NullStream::NullStream() { @@ -32,4 +33,26 @@ namespace AppInstaller m_executionStage = executionStage; m_comProgressCallback(ReportType::ExecutionPhaseUpdate, 0, 0, ProgressType::None, m_executionStage); } -}- \ No newline at end of file + + void COMContext::SetLoggerContext(const std::wstring_view telemetryCorelationJson, const std::string& caller) + { + Logging::SetActivityId(); + Logging::Telemetry().SetTelemetryCorelationJson(telemetryCorelationJson); + Logging::Telemetry().SetCaller(caller); + Logging::Telemetry().LogStartup(true); + } + + void COMContext::SetLoggers() + { + Logging::Log().SetLevel(Logging::Level::Verbose); + Logging::Log().EnableChannel(Logging::Channel::All); + + // TODO: Log to file for COM API calls only when debugging in visual studio + Logging::AddFileLogger(s_comLogFileNamePrefix); + Logging::BeginLogFileCleanup(); + + Logging::AddTraceLogger(); + + Logging::EnableWilFailureTelemetry(); + } +} diff --git a/src/AppInstallerCLICore/COMContext.h b/src/AppInstallerCLICore/COMContext.h @@ -61,8 +61,16 @@ namespace AppInstaller m_comProgressCallback = std::move(f); } + // Set COM call context for diagnostic and telemetry loggers + // This should be called for every COMContext object instance + void SetLoggerContext(const std::wstring_view telemetryCorelationJson, const std::string& caller); + + // Set Diagnostic and Telemetry loggers, Wil failure callback + // This should be called only once per COM Server instance + static void SetLoggers(); + private: CLI::Workflow::ExecutionStage m_executionStage = CLI::Workflow::ExecutionStage::Initial; ProgressCallBackFunction m_comProgressCallback; }; -}- \ No newline at end of file +} diff --git a/src/AppInstallerCLICore/Core.cpp b/src/AppInstallerCLICore/Core.cpp @@ -55,6 +55,7 @@ namespace AppInstaller::CLI // Set output to UTF8 ConsoleOutputCPRestore utf8CP(CP_UTF8); + Logging::Telemetry().SetCaller("winget-cli"); Logging::Telemetry().LogStartup(); // Initiate the background cleanup of the log file location. diff --git a/src/AppInstallerCLICore/Workflows/ShellExecuteInstallerHandler.cpp b/src/AppInstallerCLICore/Workflows/ShellExecuteInstallerHandler.cpp @@ -138,6 +138,7 @@ namespace AppInstaller::CLI::Workflow auto path = Runtime::GetPathTo(Runtime::PathName::DefaultLogLocation); path /= Logging::FileLogger::DefaultPrefix(); + path += '-'; path += Utility::ConvertToUTF16(manifest.Id + '.' + manifest.Version); path += '-'; path += Utility::GetCurrentTimeForFilename(); diff --git a/src/AppInstallerCLITests/main.cpp b/src/AppInstallerCLITests/main.cpp @@ -73,7 +73,7 @@ int main(int argc, char** argv) else if ("-logto"s == argv[i]) { ++i; - Logging::AddFileLogger(argv[i]); + Logging::AddFileLogger(std::string_view{ argv[i] }); } else if ("-tdd"s == argv[i]) { diff --git a/src/AppInstallerCommonCore/AppInstallerCommonCore.vcxproj b/src/AppInstallerCommonCore/AppInstallerCommonCore.vcxproj @@ -301,6 +301,7 @@ <ClInclude Include="Public\winget\ManifestSchemaValidation.h" /> <ClInclude Include="Public\winget\Resources.h" /> <ClInclude Include="Public\winget\Settings.h" /> + <ClInclude Include="Public\winget\TraceLogger.h" /> <ClInclude Include="Public\winget\UserSettings.h" /> <ClInclude Include="Public\winget\Yaml.h" /> <ClInclude Include="Telemetry\MicrosoftTelemetry.h" /> @@ -360,6 +361,7 @@ <ClCompile Include="Synchronization.cpp" /> <ClCompile Include="Telemetry\TraceLogging.cpp" /> <ClCompile Include="Architecture.cpp" /> + <ClCompile Include="TraceLogger.cpp" /> <ClCompile Include="UserSettings.cpp" /> <ClCompile Include="Versions.cpp" /> <ClCompile Include="Yaml.cpp" /> diff --git a/src/AppInstallerCommonCore/AppInstallerCommonCore.vcxproj.filters b/src/AppInstallerCommonCore/AppInstallerCommonCore.vcxproj.filters @@ -171,6 +171,9 @@ <ClInclude Include="DODownloader.h"> <Filter>Header Files</Filter> </ClInclude> + <ClInclude Include="Public\winget\TraceLogger.h"> + <Filter>Public\winget</Filter> + </ClInclude> </ItemGroup> <ItemGroup> <ClCompile Include="pch.cpp"> @@ -290,6 +293,9 @@ <ClCompile Include="DODownloader.cpp"> <Filter>Source Files</Filter> </ClCompile> + <ClCompile Include="TraceLogger.cpp"> + <Filter>Source Files</Filter> + </ClCompile> </ItemGroup> <ItemGroup> <None Include="PropertySheet.props" /> diff --git a/src/AppInstallerCommonCore/AppInstallerLogging.cpp b/src/AppInstallerCommonCore/AppInstallerLogging.cpp @@ -4,6 +4,7 @@ #include "Public/AppInstallerLogging.h" #include "Public/AppInstallerFileLogger.h" +#include "Public/winget/TraceLogger.h" #include "Public/AppInstallerTelemetry.h" #include "Public/AppInstallerDateTime.h" #include "Public/AppInstallerRuntime.h" @@ -129,11 +130,26 @@ namespace AppInstaller::Logging } } + void AddFileLogger() + { + Log().AddLogger(std::make_unique<FileLogger>()); + } + void AddFileLogger(const std::filesystem::path& filePath) { Log().AddLogger(std::make_unique<FileLogger>(filePath)); } + void AddFileLogger(std::string_view fileNamePrefix) + { + Log().AddLogger(std::make_unique<FileLogger>(fileNamePrefix)); + } + + void AddTraceLogger() + { + Log().AddLogger(std::make_unique<TraceLogger>()); + } + void BeginLogFileCleanup() { FileLogger::BeginCleanup(Runtime::GetPathTo(Runtime::PathName::DefaultLogLocation)); diff --git a/src/AppInstallerCommonCore/AppInstallerTelemetry.cpp b/src/AppInstallerCommonCore/AppInstallerTelemetry.cpp @@ -11,6 +11,15 @@ #define AICLI_TraceLoggingStringView(_sv_,_name_) TraceLoggingCountedUtf8String(_sv_.data(), static_cast<ULONG>(_sv_.size()), _name_) #define AICLI_TraceLoggingWStringView(_sv_,_name_) TraceLoggingCountedWideString(_sv_.data(), static_cast<ULONG>(_sv_.size()), _name_) +#define AICLI_TraceLoggingWriteActivity(_eventName_,...) TraceLoggingWriteActivity(\ +g_hTraceProvider,\ +_eventName_,\ +GetActivityId(false),\ +nullptr,\ +TraceLoggingCountedUtf8String(m_caller.c_str(), static_cast<ULONG>(m_caller.size()), "Caller"),\ +TraceLoggingPackedFieldEx(m_telemetryCorelationJsonW.c_str(), static_cast<ULONG>((m_telemetryCorelationJsonW.size() + 1) * sizeof(wchar_t)), TlgInUNICODESTRING, TlgOutJSON, "CvJson"),\ +__VA_ARGS__) + // Helper to print a GUID std::ostream& operator<<(std::ostream& out, const GUID& guid) { @@ -53,12 +62,21 @@ namespace AppInstaller::Logging (void)CoCreateGuid(&result); return result; } + } - const GUID* GetActivityId() + const GUID* GetActivityId(bool isNewActivity) + { + static GUID activityId; + if (isNewActivity == true) { - static GUID activityId = CreateGuid(); - return &activityId; + activityId = CreateGuid(); } + return &activityId; + } + + void SetActivityId() + { + GetActivityId(true); } TelemetryTraceLogger::TelemetryTraceLogger() @@ -91,16 +109,46 @@ namespace AppInstaller::Logging m_isRuntimeEnabled = true; } + void TelemetryTraceLogger::SetTelemetryCorelationJson(const std::wstring_view jsonStr_view) noexcept + { + // Check if passed in string is a valid Json formatted before returning the value + // If invalid, return empty Json + Json::CharReaderBuilder jsonBuilder; + std::unique_ptr<Json::CharReader> jsonReader(jsonBuilder.newCharReader()); + std::unique_ptr<Json::Value> pJsonValue = std::make_unique<Json::Value>(); + std::string errors; + std::wstring jsonStrW{ jsonStr_view }; + std::string jsonStr = ConvertToUTF8(jsonStrW.c_str()); + + bool result = jsonReader->parse(jsonStr.c_str(), + jsonStr.c_str() + jsonStr.size(), + pJsonValue.get(), + &errors); + + if (result) + { + m_telemetryCorelationJsonW = jsonStrW; + AICLI_LOG(Core, Info, << "Passed in Corelation Vector Json is valid: " << jsonStr); + } + else + { + AICLI_LOG(Core, Error, << "Passed in Corelation Vector Json is invalid: " << jsonStr << "; Error: " << errors); + } + } + + void TelemetryTraceLogger::SetCaller(const std::string& caller) + { + m_caller = caller; + } + void TelemetryTraceLogger::LogFailure(const wil::FailureInfo& failure) const noexcept { if (IsTelemetryEnabled()) { auto anonMessage = AnonymizeString(failure.pszMessage); - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "FailureInfo", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), TraceLoggingHResult(failure.hr, "HResult"), AICLI_TraceLoggingWStringView(anonMessage, "Message"), @@ -116,13 +164,13 @@ namespace AppInstaller::Logging // Also send failure to the log AICLI_LOG(Fail, Error, << [&]() { - wchar_t message[2048]; - GetFailureLogString(message, ARRAYSIZE(message), failure); - return Utility::ConvertToUTF8(message); + wchar_t message[2048]; + GetFailureLogString(message, ARRAYSIZE(message), failure); + return Utility::ConvertToUTF8(message); }()); } - void TelemetryTraceLogger::LogStartup() const noexcept + void TelemetryTraceLogger::LogStartup(bool isCOMCall) const noexcept { LocIndString version = Runtime::GetClientVersion(); LocIndString packageVersion; @@ -133,33 +181,31 @@ namespace AppInstaller::Logging if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "ClientVersion", - GetActivityId(), - nullptr, + TraceLoggingBool(isCOMCall, "IsCOMCall"), TraceLoggingCountedString(version->c_str(), static_cast<ULONG>(version->size()), "Version"), TraceLoggingCountedString(packageVersion->c_str(), static_cast<ULONG>(packageVersion->size()), "PackageVersion"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), TraceLoggingKeyword(MICROSOFT_KEYWORD_CRITICAL_DATA)); } - AICLI_LOG(Core, Info, << "WinGet, version [" << version << "], activity [" << *GetActivityId() << ']'); + AICLI_LOG(Core, Info, << "WinGet, version [" << version << "], activity [" << *GetActivityId(false) << ']'); AICLI_LOG(Core, Info, << "OS: " << Runtime::GetOSVersion()); AICLI_LOG(Core, Info, << "Command line Args: " << Utility::ConvertToUTF8(GetCommandLineW())); if (Runtime::IsRunningInPackagedContext()) { AICLI_LOG(Core, Info, << "Package: " << packageVersion); } + AICLI_LOG(Core, Info, << "IsCOMCall:" << isCOMCall << "; Caller: " << m_caller); } - + void TelemetryTraceLogger::LogCommand(std::string_view commandName) const noexcept { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "CommandFound", - GetActivityId(), - nullptr, AICLI_TraceLoggingStringView(commandName, "Command"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance | PDT_ProductAndServiceUsage), TraceLoggingKeyword(MICROSOFT_KEYWORD_CRITICAL_DATA)); @@ -172,10 +218,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "CommandSuccess", - GetActivityId(), - nullptr, AICLI_TraceLoggingStringView(commandName, "Command"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), TraceLoggingKeyword(MICROSOFT_KEYWORD_CRITICAL_DATA)); @@ -188,10 +232,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "CommandTermination", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), TraceLoggingHResult(hr, "HResult"), AICLI_TraceLoggingStringView(file, "File"), @@ -210,10 +252,8 @@ namespace AppInstaller::Logging { auto anonMessage = AnonymizeString(Utility::ConvertToUTF16(message)); - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "Exception", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), AICLI_TraceLoggingStringView(commandName, "Command"), AICLI_TraceLoggingStringView(type, "Type"), @@ -230,10 +270,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "GetManifest", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), TraceLoggingBool(isLocalManifest, "IsManifestLocal"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), @@ -245,13 +283,11 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "ManifestFields", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), AICLI_TraceLoggingStringView(id, "Id"), - AICLI_TraceLoggingStringView(name,"Name"), + AICLI_TraceLoggingStringView(name, "Name"), AICLI_TraceLoggingStringView(version, "Version"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), TraceLoggingKeyword(MICROSOFT_KEYWORD_CRITICAL_DATA)); @@ -264,10 +300,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "NoAppMatch", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), TraceLoggingKeyword(MICROSOFT_KEYWORD_CRITICAL_DATA)); @@ -280,10 +314,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "MultiAppMatch", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), TraceLoggingKeyword(MICROSOFT_KEYWORD_CRITICAL_DATA)); @@ -296,10 +328,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "AppFound", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), AICLI_TraceLoggingStringView(name, "Name"), AICLI_TraceLoggingStringView(id, "Id"), @@ -314,10 +344,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "SelectedInstaller", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), TraceLoggingInt32(arch, "Arch"), AICLI_TraceLoggingStringView(url, "Url"), @@ -349,10 +377,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "SearchRequest", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), AICLI_TraceLoggingStringView(type, "Type"), AICLI_TraceLoggingStringView(query, "Query"), @@ -372,10 +398,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "SearchResultCount", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), TraceLoggingUInt64(resultCount, "ResultCount"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), @@ -393,10 +417,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "HashMismatch", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), AICLI_TraceLoggingStringView(id, "Id"), AICLI_TraceLoggingStringView(version, "Version"), @@ -420,10 +442,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "InstallerFailure", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), AICLI_TraceLoggingStringView(id, "Id"), AICLI_TraceLoggingStringView(version, "Version"), @@ -441,10 +461,8 @@ namespace AppInstaller::Logging { if (IsTelemetryEnabled()) { - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "UninstallerFailure", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), AICLI_TraceLoggingStringView(id, "Id"), AICLI_TraceLoggingStringView(version, "Version"), @@ -481,10 +499,8 @@ namespace AppInstaller::Logging } catch (...) {} - TraceLoggingWriteActivity(g_hTelemetryProvider, + AICLI_TraceLoggingWriteActivity( "InstallARPChange", - GetActivityId(), - nullptr, TraceLoggingUInt32(s_subExecutionId, "SubExecutionId"), AICLI_TraceLoggingStringView(sourceIdentifier, "SourceIdentifier"), AICLI_TraceLoggingStringView(packageIdentifier, "PackageIdentifier"), @@ -590,4 +606,4 @@ namespace AppInstaller::Logging s_TelemetryTraceLogger_TestOverride = std::move(ttl); } #endif -}- \ No newline at end of file +} diff --git a/src/AppInstallerCommonCore/FileLogger.cpp b/src/AppInstallerCommonCore/FileLogger.cpp @@ -13,22 +13,24 @@ namespace AppInstaller::Logging using namespace std::string_view_literals; using namespace std::chrono_literals; - static constexpr std::string_view s_fileLoggerDefaultFilePrefix = "WinGet-"sv; + static constexpr std::string_view s_fileLoggerDefaultFilePrefix = "WinGet"sv; static constexpr std::string_view s_fileLoggerDefaultFileExt = ".log"sv; + FileLogger::FileLogger() : FileLogger(s_fileLoggerDefaultFilePrefix) {} + FileLogger::FileLogger(const std::filesystem::path& filePath) { - if (filePath.empty()) - { - m_name = "file"; - m_filePath = Runtime::GetPathTo(Runtime::PathName::DefaultLogLocation); - m_filePath /= s_fileLoggerDefaultFilePrefix.data() + Utility::GetCurrentTimeForFilename() + s_fileLoggerDefaultFileExt.data(); - } - else - { - m_name = GetNameForPath(filePath); - m_filePath = filePath; - } + m_name = GetNameForPath(filePath); + m_filePath = filePath; + + m_stream.open(m_filePath); + } + + FileLogger::FileLogger(const std::string_view fileNamePrefix) + { + m_name = "file"; + m_filePath = Runtime::GetPathTo(Runtime::PathName::DefaultLogLocation); + m_filePath /= fileNamePrefix.data() + ('-' + Utility::GetCurrentTimeForFilename() + s_fileLoggerDefaultFileExt.data()); m_stream.open(m_filePath); } @@ -83,8 +85,7 @@ namespace AppInstaller::Logging for (auto& file : std::filesystem::directory_iterator{ filePath }) { if (file.is_regular_file() && - now - file.last_write_time() > (7 * 24h) && - Utility::CaseInsensitiveStartsWith(file.path().filename().string(), s_fileLoggerDefaultFilePrefix)) + now - file.last_write_time() > (7 * 24h)) { std::filesystem::remove(file.path()); } diff --git a/src/AppInstallerCommonCore/Public/AppInstallerFileLogger.h b/src/AppInstallerCommonCore/Public/AppInstallerFileLogger.h @@ -13,7 +13,9 @@ namespace AppInstaller::Logging // Logs to a file. struct FileLogger : public ILogger { - FileLogger(const std::filesystem::path& filePath = {}); + FileLogger(); + explicit FileLogger(const std::filesystem::path& filePath); + explicit FileLogger(const std::string_view fileNamePrefix); ~FileLogger(); @@ -29,9 +31,9 @@ namespace AppInstaller::Logging static std::string_view DefaultExt(); // ILogger - virtual std::string GetName() const override; + std::string GetName() const override; - virtual void Write(Channel channel, Level level, std::string_view message) noexcept override; + void Write(Channel channel, Level level, std::string_view message) noexcept override; // Starts a background task to clean up old log files. static void BeginCleanup(const std::filesystem::path& filePath); diff --git a/src/AppInstallerCommonCore/Public/AppInstallerLogging.h b/src/AppInstallerCommonCore/Public/AppInstallerLogging.h @@ -133,7 +133,12 @@ namespace AppInstaller::Logging } // Adds the default file logger to the DiagnosticLogger. - void AddFileLogger(const std::filesystem::path& filePath = {}); + void AddFileLogger(); + void AddFileLogger(const std::filesystem::path& filePath); + void AddFileLogger(std::string_view fileNamePrefix); + + // Adds the trace logger to the DiagnosticLogger. + void AddTraceLogger(); // Starts a background task to clean up old log files. void BeginLogFileCleanup(); diff --git a/src/AppInstallerCommonCore/Public/AppInstallerTelemetry.h b/src/AppInstallerCommonCore/Public/AppInstallerTelemetry.h @@ -30,11 +30,17 @@ namespace AppInstaller::Logging bool DisableRuntime(); void EnableRuntime(); + // Store the passed in name of the Caller for COM calls + void SetCaller(const std::string& caller); + + // Store the passed in Telemetry Corelation Json for COM calls + void SetTelemetryCorelationJson(const std::wstring_view jsonStr_view) noexcept; + // Logs the failure info. void LogFailure(const wil::FailureInfo& failure) const noexcept; // Logs the initial process startup. - void LogStartup() const noexcept; + void LogStartup(bool isCOMCall = false) const noexcept; // Logs the invoked command. void LogCommand(std::string_view commandName) const noexcept; @@ -127,6 +133,9 @@ namespace AppInstaller::Logging bool m_isSettingEnabled = true; std::atomic_bool m_isRuntimeEnabled{ true }; + std::wstring m_telemetryCorelationJsonW = L"{}"; + std::string m_caller; + // Data that is needed by AnonymizeString std::wstring m_userProfile; }; @@ -137,6 +146,11 @@ namespace AppInstaller::Logging // Turns on wil failure telemetry and logging. void EnableWilFailureTelemetry(); + const GUID* GetActivityId(bool isNewActivity); + + // Set ActivityId + void SetActivityId(); + // An RAII object to disable telemetry during its lifetime. // Primarily used by the complete command to prevent messy input from spamming us. struct DisableTelemetryScope diff --git a/src/AppInstallerCommonCore/Public/winget/TraceLogger.h b/src/AppInstallerCommonCore/Public/winget/TraceLogger.h @@ -0,0 +1,24 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. +#pragma once +#include <AppInstallerLogging.h> +#include <AppInstallerTelemetry.h> + +#include <string> +#include <string_view> + +namespace AppInstaller::Logging +{ + // Log ETW events for tracing. + // Doesn't save events to a file on disk. + struct TraceLogger : ILogger + { + TraceLogger() = default; + + ~TraceLogger() = default; + + // ILogger + std::string GetName() const override; + void Write(Channel channel, Level, std::string_view message) noexcept override; + }; +} diff --git a/src/AppInstallerCommonCore/Telemetry/TraceLogging.cpp b/src/AppInstallerCommonCore/Telemetry/TraceLogging.cpp @@ -6,7 +6,7 @@ // GUID for Microsoft.PackageManager.Client : {c0cf606f-569b-5c20-27d9-88a745fa2175} TRACELOGGING_DEFINE_PROVIDER( - g_hTelemetryProvider, + g_hTraceProvider, "Microsoft.PackageManager.Client", (0xc0cf606f, 0x569b, 0x5c20, 0x27, 0xd9, 0x88, 0xa7, 0x45, 0xfa, 0x21, 0x75), TraceLoggingOptionMicrosoftTelemetry()); @@ -14,7 +14,6 @@ TRACELOGGING_DEFINE_PROVIDER( bool g_IsTelemetryProviderEnabled{}; UCHAR g_TelemetryProviderLevel{}; ULONGLONG g_TelemetryProviderMatchAnyKeyword{}; -GUID g_TelemetryProviderActivityId{}; void WINAPI TelemetryProviderEnabledCallback( _In_ LPCGUID /*sourceId*/, @@ -32,27 +31,10 @@ void WINAPI TelemetryProviderEnabledCallback( void RegisterTraceLogging() { - HRESULT hr = S_OK; - - TraceLoggingRegisterEx(g_hTelemetryProvider, TelemetryProviderEnabledCallback, nullptr); - //Generate the ActivityId used to track the session - hr = CoCreateGuid(&g_TelemetryProviderActivityId); - if (FAILED(hr)) - { - TraceLoggingWriteActivity( - g_hTelemetryProvider, - "CreateGuidError", - nullptr, - nullptr, - TraceLoggingHResult(hr), - TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), - TraceLoggingKeyword(MICROSOFT_KEYWORD_CRITICAL_DATA)); - - g_TelemetryProviderActivityId = GUID_NULL; - }; + TraceLoggingRegisterEx(g_hTraceProvider, TelemetryProviderEnabledCallback, nullptr); } void UnRegisterTraceLogging() { - TraceLoggingUnregister(g_hTelemetryProvider); + TraceLoggingUnregister(g_hTraceProvider); } diff --git a/src/AppInstallerCommonCore/Telemetry/TraceLogging.h b/src/AppInstallerCommonCore/Telemetry/TraceLogging.h @@ -60,11 +60,10 @@ // TraceLogging provider name for telemetry. #define TELEMETRY_PROVIDER_NAME "Microsoft.PackageManager.Client" -TRACELOGGING_DECLARE_PROVIDER(g_hTelemetryProvider); +TRACELOGGING_DECLARE_PROVIDER(g_hTraceProvider); extern bool g_IsTelemetryProviderEnabled; extern UCHAR g_TelemetryProviderLevel; extern ULONGLONG g_TelemetryProviderMatchAnyKeyword; -extern GUID g_TelemetryProviderActivityId; extern void RegisterTraceLogging(); extern void UnRegisterTraceLogging(); diff --git a/src/AppInstallerCommonCore/TraceLogger.cpp b/src/AppInstallerCommonCore/TraceLogger.cpp @@ -0,0 +1,30 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. +#include "pch.h" +#include "Public/winget/TraceLogger.h" +#include "Public/AppInstallerTelemetry.h" + +namespace AppInstaller::Logging +{ + void TraceLogger::Write(Channel channel, Level, std::string_view message) noexcept try + { + // Send to a string first to create a single block to log to a trace. + std::stringstream strstr; + strstr << std::chrono::system_clock::now() << " [" << std::setw(GetMaxChannelNameLength()) << std::left << std::setfill(' ') << GetChannelName(channel) << "] " << message << std::endl; + + TraceLoggingWriteActivity(g_hTraceProvider, + "Diagnostics", + AppInstaller::Logging::GetActivityId(false), + nullptr, + TraceLoggingString(strstr.str().c_str(), "LogMessage")); + } + catch (...) + { + // Just eat any exceptions here; better to lose logs than functionality + } + + std::string TraceLogger::GetName() const + { + return "Trace"; + } +} diff --git a/src/WinGetUtil/Exports.cpp b/src/WinGetUtil/Exports.cpp @@ -34,6 +34,7 @@ extern "C" if (!AppInstaller::Logging::Log().ContainsLogger(loggerName)) { + // Let FileLogger use default file prefix AppInstaller::Logging::AddFileLogger(pathAsPath); }