Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 10 additions & 0 deletions doc/Settings.md
Original file line number Diff line number Diff line change
Expand Up @@ -326,6 +326,16 @@ Sets the default strategy for naming log files for installers that support it. `
},
```

### format

Sets the format used when writing log entries to a file. `winget` is the default and uses the standard WinGet log format. `ccm` writes entries in a [CMTrace](https://learn.microsoft.com/mem/configmgr/core/support/cmtrace)-compatible format, which is useful when collecting winget logs alongside Configuration Manager (CCM) logs. Invalid values will revert to `winget`.

```json
"logging": {
"format": "winget" | "ccm"
},
```

### file

The `file` settings control the log files generated by winget during operation. These settings apply to the automatic cleanup that happens whenever a Windows Package Manager process is run.
Expand Down
8 changes: 8 additions & 0 deletions schemas/JSON/settings/settings.schema.0.2.json
Original file line number Diff line number Diff line change
Expand Up @@ -91,6 +91,14 @@
"shortguid"
]
},
"format": {
"description": "The format used when writing log entries to a file",
"type": "string",
"enum": [
"winget",
"ccm"
]
},
"file": {
"description": "The file settings control the log files generated by winget during operation.",
"type": "object",
Expand Down
43 changes: 43 additions & 0 deletions src/AppInstallerCLITests/FileLogger.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,13 @@
// Licensed under the MIT License.
#include "pch.h"
#include "TestCommon.h"
#include "TestSettings.h"
#include "TestHooks.h"
#include <AppInstallerFileLogger.h>
#include <AppInstallerStrings.h>
#include <winget/Settings.h>

#include <regex>

using namespace AppInstaller::Logging;
using namespace AppInstaller::Utility;
Expand Down Expand Up @@ -206,6 +211,44 @@ TEST_CASE("FileLogger_MaximumSize", "[logging]")
FileLogger_MaximumSize_Test(tagState, sizeState);
}

TEST_CASE("FileLogger_CCMFormat", "[logging]")

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure this test and the new imports are necessary, since there isn't one for the existing format. Figured I'd submit just in case

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this and more tests should be present if we are writing to a defined format that needs to be parseable. The existing format is just "some text" that happens to have a logical format, but doesn't need to be computer readable.

I would want more unit tests that ensure the specifics of the automatic fields and more extensive coverage on the text portion's escaping.

I would also suggest some mechanism to force the entire E2E run in the pipeline to additionally generate CCM logs that could have a post-run validation applied to ensure compat.

{
// The CCM/CMTrace log format is opt-in via the "logging.format" user setting; override it for this test.
auto settingsGuard = DeleteUserSettingsFiles();
SetSetting(AppInstaller::Settings::Stream::PrimaryUserSettings, R"({ "logging": { "format": "ccm" } })");
UserSettingsTest userSettings;
TestHook::SetUserSettings_Override userSettingsOverride{ userSettings };
Comment on lines +217 to +220

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This appears to be both writing the actual settings file and overriding it via the hook. You should just use the hook if you can. (Although with a different CCMLogger type you wouldn't even need that.)


// CCM type: 1=Info/Verbose, 2=Warning, 3=Error/Critical.
Level level = Level::Info;
int expectedType = 1;
SECTION("Verbose maps to type 1") { level = Level::Verbose; expectedType = 1; }
SECTION("Info maps to type 1") { level = Level::Info; expectedType = 1; }
SECTION("Warning maps to type 2") { level = Level::Warning; expectedType = 2; }
SECTION("Error maps to type 3") { level = Level::Error; expectedType = 3; }
SECTION("Crit maps to type 3") { level = Level::Crit; expectedType = 3; }

const std::string message = "CCM format test message";

TempFile tempFile{ "FileLogger_CCM", ".log" };
INFO("File: " << tempFile.GetPath().u8string());
{
FileLogger logger{ tempFile };
logger.Write(DefaultChannel, level, message);
}

std::ifstream fileStream{ tempFile.GetPath(), std::ios::binary };
auto fileContents = ReadEntireStream(fileStream);
INFO("File contents: " << fileContents);

// Expected: <![LOG[<message>]LOG]!><time="HH:MM:SS.mmm+<bias>" date="MM-DD-YYYY" component="<channel>" context="" type="<N>" thread="<id>" file="">
std::regex ccmPattern{
R"(^<!\[LOG\[CCM format test message\]LOG\]!><time="\d{2}:\d{2}:\d{2}\.\d{3}\+-?\d+" date="\d{2}-\d{2}-\d{4}" component="[^"]*" context="" type=")"
+ std::to_string(expectedType)
+ R"(" thread="\d+" file="">)" };
REQUIRE(std::regex_search(fileContents, ccmPattern));
}

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It feels like we should be using an XML parser here and actually validating the time/date/thread etc.


TEST_CASE("FileLogger_MaximumSize_ManyWraps", "[logging]")
{
TempFile tempFile{ "FileLogger_ManyWraps", ".log" };
Expand Down
58 changes: 58 additions & 0 deletions src/AppInstallerCLITests/UserSettings.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -386,6 +386,64 @@ TEST_CASE("SettingLoggingFileNameStrategy", "[settings]") {
}
}

TEST_CASE("SettingLoggingFormat", "[settings]")
{
auto again = DeleteUserSettingsFiles();

SECTION("Default value")
{
UserSettingsTest userSettingTest;

REQUIRE(userSettingTest.Get<Setting::LoggingFormat>() == LogFileFormat::WinGet);
REQUIRE(userSettingTest.GetWarnings().size() == 0);
}
SECTION("WinGet")
{
std::string_view json = R"({ "logging": { "format": "winget" } })";
SetSetting(Stream::PrimaryUserSettings, json);
UserSettingsTest userSettingTest;

REQUIRE(userSettingTest.Get<Setting::LoggingFormat>() == LogFileFormat::WinGet);
REQUIRE(userSettingTest.GetWarnings().size() == 0);
}
SECTION("CCM")
{
std::string_view json = R"({ "logging": { "format": "ccm" } })";
SetSetting(Stream::PrimaryUserSettings, json);
UserSettingsTest userSettingTest;

REQUIRE(userSettingTest.Get<Setting::LoggingFormat>() == LogFileFormat::CCM);
REQUIRE(userSettingTest.GetWarnings().size() == 0);
}
SECTION("Case insensitive CCM")
{
std::string_view json = R"({ "logging": { "format": "CCM" } })";
SetSetting(Stream::PrimaryUserSettings, json);
UserSettingsTest userSettingTest;

REQUIRE(userSettingTest.Get<Setting::LoggingFormat>() == LogFileFormat::CCM);
REQUIRE(userSettingTest.GetWarnings().size() == 0);
}
SECTION("Bad value")
{
std::string_view json = R"({ "logging": { "format": "cmtrace" } })";
SetSetting(Stream::PrimaryUserSettings, json);
UserSettingsTest userSettingTest;

REQUIRE(userSettingTest.Get<Setting::LoggingFormat>() == LogFileFormat::WinGet);
REQUIRE(userSettingTest.GetWarnings().size() == 1);
}
SECTION("Bad value type")
{
std::string_view json = R"({ "logging": { "format": true } })";
SetSetting(Stream::PrimaryUserSettings, json);
UserSettingsTest userSettingTest;

REQUIRE(userSettingTest.Get<Setting::LoggingFormat>() == LogFileFormat::WinGet);
REQUIRE(userSettingTest.GetWarnings().size() == 1);
}
}

TEST_CASE("SettingAutoUpdateIntervalInMinutes", "[settings]")
{
auto again = DeleteUserSettingsFiles();
Expand Down
56 changes: 55 additions & 1 deletion src/AppInstallerCommonCore/FileLogger.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,52 @@ namespace AppInstaller::Logging
return std::move(strstr).str();
}

// Formats a log line in CCM (CMTrace-compatible) format.
std::string ToCCMLogLine(Channel channel, Level level, std::string_view message)
{
auto now = std::chrono::system_clock::now();
auto tt = std::chrono::system_clock::to_time_t(now);
tm localTime{};
_localtime64_s(&localTime, &tt);

auto sinceEpoch = now.time_since_epoch();
auto leftoverMillis = std::chrono::duration_cast<std::chrono::milliseconds>(sinceEpoch) - std::chrono::duration_cast<std::chrono::seconds>(sinceEpoch);

// Get UTC bias in minutes (positive means west of UTC, CMTrace uses positive for west)
long timezoneBiasSeconds = 0;
_get_timezone(&timezoneBiasSeconds);
long biasMins = timezoneBiasSeconds / 60;

// CCM type: 1=Info/Verbose, 2=Warning, 3=Error/Critical
int type;
switch (level)
{
case Level::Warning: type = 2; break;
case Level::Error:
case Level::Crit: type = 3; break;
default: type = 1; break;
}

std::stringstream strstr;
strstr << "<![LOG[" << message << "]LOG]!>"

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there any mechanism to escape ]LOG]!> (or whatever substring actually indicates the end of the log), or does the format just expect that would never be part of a normal log? I don't want us to have to scan every log string, but it is the correct thing to do. If there is no official escape, we could replace it with some slightly modified version (ex. |LOG|!>).

<< "<time=\""
<< std::setw(2) << std::setfill('0') << localTime.tm_hour << ":"
<< std::setw(2) << std::setfill('0') << localTime.tm_min << ":"
<< std::setw(2) << std::setfill('0') << localTime.tm_sec << "."
<< std::setw(3) << std::setfill('0') << leftoverMillis.count()
<< "+" << biasMins << "\""
<< " date=\""
<< std::setw(2) << std::setfill('0') << (1 + localTime.tm_mon) << "-"
<< std::setw(2) << std::setfill('0') << localTime.tm_mday << "-"
<< (1900 + localTime.tm_year) << "\""
<< " component=\"" << GetChannelName(channel) << "\""
<< " context=\"\""

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might be an opportunity to include a correlation vector or similar here.

<< " type=\"" << type << "\""
<< " thread=\"" << GetCurrentThreadId() << "\""
<< " file=\"\">";
return std::move(strstr).str();
}

// Determines the difference between the given position and the maximum as an offset.
std::ofstream::off_type CalculateDiff(const std::ofstream::pos_type& position, std::ofstream::off_type maximum)
{
Expand Down Expand Up @@ -94,7 +140,15 @@ namespace AppInstaller::Logging

void FileLogger::Write(Channel channel, Level level, std::string_view message) noexcept try
{
std::string log = ToLogLine(channel, level, message);
std::string log;
if (Settings::User().Get<Settings::Setting::LoggingFormat>() == LogFileFormat::CCM)
{
log = ToCCMLogLine(channel, level, message);
}
else
{
log = ToLogLine(channel, level, message);
}
Comment on lines +144 to +151

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would prefer the CCM logger to be its own type. It should be as easy as deriving from FileLogger and overriding the Write* methods as appropriate. Then use the setting during the initialization to choose between the two options.

WriteDirect(channel, level, log);
}
catch (...) {}
Expand Down
2 changes: 2 additions & 0 deletions src/AppInstallerCommonCore/Public/winget/UserSettings.h
Original file line number Diff line number Diff line change
Expand Up @@ -133,6 +133,7 @@ namespace AppInstaller::Settings
LoggingFileTotalSizeLimitInMB,
LoggingFileIndividualSizeLimitInMB,
LoggingFileCountLimit,
LoggingFormat,
// Uninstall behavior
UninstallPurgePortablePackage,
// Download behavior
Expand Down Expand Up @@ -237,6 +238,7 @@ namespace AppInstaller::Settings
SETTINGMAPPING_SPECIALIZATION(Setting::LoggingFileTotalSizeLimitInMB, uint32_t, uint32_t, 128, ".logging.file.totalSizeLimitInMB"sv);
SETTINGMAPPING_SPECIALIZATION(Setting::LoggingFileIndividualSizeLimitInMB, uint32_t, uint32_t, 16, ".logging.file.individualSizeLimitInMB"sv);
SETTINGMAPPING_SPECIALIZATION(Setting::LoggingFileCountLimit, uint32_t, uint32_t, 0, ".logging.file.countLimit"sv);
SETTINGMAPPING_SPECIALIZATION(Setting::LoggingFormat, std::string, Logging::LogFileFormat, Logging::LogFileFormat::WinGet, ".logging.format"sv);
// Interactivity
SETTINGMAPPING_SPECIALIZATION(Setting::InteractivityDisable, bool, bool, false, ".interactivity.disable"sv);
// Output behavior
Expand Down
16 changes: 16 additions & 0 deletions src/AppInstallerCommonCore/UserSettings.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -530,6 +530,22 @@ namespace AppInstaller::Settings
return value * 24h;
}

WINGET_VALIDATE_SIGNATURE(LoggingFormat)
{
static constexpr std::string_view s_format_winget = "winget";
static constexpr std::string_view s_format_ccm = "ccm";

if (Utility::CaseInsensitiveEquals(value, s_format_winget))
{
return LogFileFormat::WinGet;
}
else if (Utility::CaseInsensitiveEquals(value, s_format_ccm))
{
return LogFileFormat::CCM;
}
return {};
}

WINGET_VALIDATE_SIGNATURE(OutputSortOrder)
{
std::vector<SortField> fields;
Expand Down
9 changes: 9 additions & 0 deletions src/AppInstallerSharedLib/Public/AppInstallerLogging.h
Original file line number Diff line number Diff line change
Expand Up @@ -98,6 +98,15 @@ namespace AppInstaller::Logging
ShortGuid,
};

// The format used when writing log entries to a file.
enum class LogFileFormat
{
// Default WinGet format: "<timestamp> <level> [channel] message"
WinGet,
// CCM/CMTrace-compatible format: "<![LOG[message]LOG]!><time="<time>" date="<date>" component="<channel>" context="" type="N" thread="<id>" file="">"
CCM,
};

// Indicates a location of significance in the logging stream.
enum class Tag
{
Expand Down
Loading