Additional logging limitations and control (#5888)

## Change
Expands the limitations on log files and allows them to be user
configurable.

The existing limit was hardcoded to remove any files over 7 days old.
This was enforced by a background thread spun up during process start.
This same thread enforces the new limits on the aggregate logging
directory, while additional code in the file logger enforces the
individual file size limitation.

When new log lines would exceed the maximum file size for an individual
file, the stream is repositioned after the initialization portion of the
log, a log line is output to indicate the wrap, and the logs continue to
overwrite the older data.

Author: JohnMcPMS

.github/actions/spelling/expect.txt

@@ -499,6 +499,7 @@ Scm
 sddl
 secureobject
 securestring
+seekp
 seof
 servercert
 servercertificate
@@ -548,6 +549,7 @@ Tagit
 TARG
 taskhostw
 tcs
+tellp
 temppath
 testexampleinstaller
 thiscouldbeapc

doc/Settings.md

@@ -286,6 +286,35 @@ In addition, there are special values that cover multiple channels.  `default` i
     },
 ```
 
+### 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.
+They only apply to the default log location, which contains winget logs, AppInstaller logs (the MSIX install UI), and is the default location where installer logs are placed.
+The automatic cleanup happens at the beginning of the process, so the log file(s) generated by the current process will not be considered in the limits.
+
+|Setting|Description|Default|Note|
+|---|---|---|---|
+|`ageLimitInDays`|The maximum age, in days, of files in the log directory; older files are deleted.|7 (days)|Set to 0 to disable this limit.|
+|`totalSizeLimitInMB`|The maximum size, in megabytes, of all files in the log directory; the oldest files are deleted first.|128 (MB)|Set to 0 to disable this limit.|
+|`countLimit`|The maximum number of files in the log directory; the oldest files are deleted first.|0|Set to 0 (the default) to disable this limit.|
+
+These settings apply to the log files that winget writes, only as they are being written.  They do not apply to files written by installers or the AppInstaller UI.
+
+|Setting|Description|Default|Note|
+|---|---|---|---|
+|`individualSizeLimitInMB`|The maximum size, in megabytes, of an individual log file. If a file would exceed this limit, the logs will wrap. Note that this limit is approximate and the actual files may exceed it by a few bytes.|16 (MB)|Set to 0 to disable this limit.|
+
+```json
+    "logging": {
+        "file": {
+            "ageLimitInDays": 7,
+            "totalSizeLimitInMB": 128,
+            "countLimit": 0,
+            "individualSizeLimitInMB": 16,
+        }
+    },
+```
+
 ## Network
 
 The `network` settings influence how winget uses the network to retrieve packages and metadata.

schemas/JSON/settings/settings.schema.0.2.json

@@ -80,6 +80,35 @@
           },
           "minItems": 0,
           "maxItems": 20
+        },
+        "file": {
+          "description": "The file settings control the log files generated by winget during operation.",
+          "type": "object",
+          "properties": {
+            "ageLimitInDays": {
+              "description": "The maximum age, in days, of a log file before it is deleted. Set to 0 to disable automatic deletion based on age.",
+              "type": "integer",
+              "default": 7,
+              "minimum": 0
+            },
+            "totalSizeLimitInMB": {
+              "description": "The maximum total size, in megabytes, of all log files. If the total size exceeds this limit, the oldest files will be deleted first. Set to 0 to disable this limit.",
+              "type": "integer",
+              "default": 128,
+              "minimum": 0
+            },
+            "countLimit": {
+              "description": "The maximum number of log files to retain. If the number of log files exceeds this limit, the oldest files will be deleted first. Set to 0 (the default) to disable this limit.",
+              "type": "integer",
+              "default": 0,
+              "minimum": 0
+            },
+            "individualSizeLimitInMB": {
+              "description": "The maximum size, in megabytes, of an individual log file. If a file would exceed this limit, new log lines will overwrite the file from the beginning. Set to 0 to disable this limit.",
+              "type": "integer",
+              "default": 16,
+              "minimum": 0
+            }
         }
       }
     },

src/AppInstallerCLITests/AppInstallerCLITests.vcxproj

@@ -243,6 +243,7 @@
     <ClCompile Include="ExperimentalFeature.cpp" />
     <ClCompile Include="ExportFlow.cpp" />
     <ClCompile Include="FileCache.cpp" />
+    <ClCompile Include="FileLogger.cpp" />
     <ClCompile Include="Filesystem.cpp" />
     <ClCompile Include="FolderFileWatcher.cpp" />
     <ClCompile Include="FontHelper.cpp" />

src/AppInstallerCLITests/AppInstallerCLITests.vcxproj.filters

@@ -389,6 +389,9 @@
     <ClCompile Include="FontHelper.cpp">
       <Filter>Source Files\Repository</Filter>
     </ClCompile>
+    <ClCompile Include="FileLogger.cpp">
+      <Filter>Source Files\Common</Filter>
+    </ClCompile>
   </ItemGroup>
   <ItemGroup>
     <None Include="PropertySheet.props" />

src/AppInstallerCLITests/FileLogger.cpp

@@ -0,0 +1,245 @@
+// Copyright (c) Microsoft Corporation.
+// Licensed under the MIT License.
+#include "pch.h"
+#include "TestCommon.h"
+#include <AppInstallerFileLogger.h>
+#include <AppInstallerStrings.h>
+
+using namespace AppInstaller::Logging;
+using namespace AppInstaller::Utility;
+using namespace TestCommon;
+
+
+std::string GetHeaderString()
+{
+    return "TIME [CHAN] Header Message";
+}
+
+std::string GetLargeString()
+{
+    return "[===|Clearly defined start to large string|===]\r\n"
+        "While this string does not need to be particularly unique, it is still good if it is not easily duplicated by any other random set of data.\r\n"
+        "It should also end in a character that is not used in any other way within these tests, so please don't include that character when writing tests.\r\n"
+        "That character is &";
+}
+
+namespace
+{
+#define WINGET_DEFINE_STRING_ENUM(_enum_,_value_) constexpr std::string_view _enum_##_##_value_ = #_value_##sv
+
+    WINGET_DEFINE_STRING_ENUM(TagState, Unset);
+    WINGET_DEFINE_STRING_ENUM(TagState, SetAtStart);
+    WINGET_DEFINE_STRING_ENUM(TagState, SetAfterLogging);
+
+    WINGET_DEFINE_STRING_ENUM(MaximumSizeState, Zero);
+    WINGET_DEFINE_STRING_ENUM(MaximumSizeState, SmallerThanLargeString);
+    WINGET_DEFINE_STRING_ENUM(MaximumSizeState, EqualToLargeString);
+    WINGET_DEFINE_STRING_ENUM(MaximumSizeState, SlightlyLargerThanLargeString);
+    WINGET_DEFINE_STRING_ENUM(MaximumSizeState, MuchLargerThanLargeString);
+
+    constexpr std::string_view WrapIndicator = "--- log file has wrapped ---"sv;
+    // The amount of extra size that is allowed (total indicator size + newline + newlines from test strings)
+    constexpr size_t ExtraAllowedSize = 68;
+
+    constexpr size_t NewLineCharacterCount = 2;
+    constexpr size_t SmallDifferenceSize = 10;
+    constexpr AppInstaller::Logging::Channel DefaultChannel = AppInstaller::Logging::Channel::Core;
+    constexpr AppInstaller::Logging::Level DefaultLevel = AppInstaller::Logging::Level::Info;
+
+    void ValidateFileContents(const std::filesystem::path& file, const std::vector<std::string_view>& expectedContents, size_t maximumSize)
+    {
+        std::ifstream fileStream{ file, std::ios::binary };
+        auto fileContents = ReadEntireStream(fileStream);
+        std::string_view fileContentsView = fileContents;
+
+        std::string fileContentsCopy = fileContents;
+        FindAndReplace(fileContentsCopy, "\r", "\\r");
+        FindAndReplace(fileContentsCopy, "\n", "\\n");
+        INFO("File contents:\n" << fileContentsCopy);
+
+        if (maximumSize)
+        {
+            REQUIRE(maximumSize + ExtraAllowedSize >= fileContents.size());
+        }
+
+        size_t currentPosition = 0;
+        for (std::string_view expectedContent : expectedContents)
+        {
+            REQUIRE(currentPosition < fileContents.size());
+
+            if (expectedContent == WrapIndicator)
+            {
+                auto endLinePosition = fileContentsView.find('\n', currentPosition);
+                REQUIRE(endLinePosition != -1);
+                REQUIRE(endLinePosition >= expectedContent.size() + NewLineCharacterCount);
+                auto actualContent = fileContentsView.substr(endLinePosition + 1 - expectedContent.size() - NewLineCharacterCount, expectedContent.size());
+                REQUIRE(expectedContent == actualContent);
+                currentPosition = endLinePosition + 1;
+            }
+            else
+            {
+                auto actualContent = fileContentsView.substr(currentPosition, expectedContent.size());
+                REQUIRE(expectedContent == actualContent);
+                currentPosition += expectedContent.size() + NewLineCharacterCount;
+            }
+        }
+    }
+
+    void FileLogger_MaximumSize_Test(std::string_view tagState, std::string_view sizeState)
+    {
+        auto headerString = GetHeaderString();
+        auto largeString = GetLargeString();
+
+        // Determine maximum size
+        size_t maximumSize = 0;
+
+        if (sizeState == MaximumSizeState_SmallerThanLargeString)
+        {
+            maximumSize = largeString.size() - SmallDifferenceSize;
+        }
+        else if (sizeState == MaximumSizeState_EqualToLargeString)
+        {
+            maximumSize = largeString.size();
+        }
+        else if (sizeState == MaximumSizeState_SlightlyLargerThanLargeString)
+        {
+            maximumSize = largeString.size() + SmallDifferenceSize;
+        }
+        else if (sizeState == MaximumSizeState_MuchLargerThanLargeString)
+        {
+            maximumSize = largeString.size() * 2;
+        }
+
+        INFO("Tag State: " << tagState << ", Size State: " << sizeState << "[" << maximumSize << "]");
+
+        TempFile tempFile{ "FileLogger_MaximumSize", ".log" };
+        FileLogger logger{ tempFile };
+
+        INFO("File: " << tempFile.GetPath().u8string());
+
+        logger.SetMaximumSize(wil::safe_cast<std::ofstream::off_type>(maximumSize));
+
+        // Set tag and log strings
+        size_t tagPosition = 0;
+        if (tagState == TagState_SetAtStart)
+        {
+            logger.SetTag(Tag::HeadersComplete);
+        }
+
+        logger.WriteDirect(DefaultChannel, DefaultLevel, headerString);
+
+        if (tagState == TagState_SetAfterLogging)
+        {
+            logger.SetTag(Tag::HeadersComplete);
+            tagPosition = headerString.size() + NewLineCharacterCount;
+        }
+
+        // Due to text output in the logger, log with \n only
+        std::string largeStringWithoutCarriageReturn = largeString;
+        FindAndReplace(largeStringWithoutCarriageReturn, "\r\n", "\n");
+
+        logger.WriteDirect(DefaultChannel, DefaultLevel, largeStringWithoutCarriageReturn);
+
+        // Calculate current state
+        size_t maximumAvailableSpace = std::numeric_limits<size_t>::max();
+        size_t currentAvailableSpace = std::numeric_limits<size_t>::max();
+        if (maximumSize)
+        {
+            maximumAvailableSpace = maximumSize - tagPosition;
+            currentAvailableSpace = maximumSize - headerString.size() - NewLineCharacterCount;
+        }
+
+        bool shouldWrap = largeString.size() > currentAvailableSpace;
+
+        INFO("Maximum Available: " << maximumAvailableSpace << ", Current Available: " << currentAvailableSpace << ", ShouldWrap: " << shouldWrap);
+
+        std::vector<std::string_view> expectedFileContents;
+
+        if (tagPosition || !shouldWrap)
+        {
+            expectedFileContents.push_back(headerString);
+        }
+
+        if (shouldWrap)
+        {
+            expectedFileContents.push_back(WrapIndicator);
+        }
+
+        std::string_view largeStringView = largeString;
+        expectedFileContents.push_back(largeStringView.substr(0, std::min(largeString.size(), maximumAvailableSpace)));
+
+        ValidateFileContents(tempFile, expectedFileContents, maximumSize);
+
+        // Log again
+        INFO("Second time logging large string");
+        logger.WriteDirect(DefaultChannel, DefaultLevel, largeStringWithoutCarriageReturn);
+
+        // The maximum size is twice the large log, so anything with a limit will wrap
+        shouldWrap = maximumSize != 0;
+
+        expectedFileContents.clear();
+
+        if (tagPosition || !shouldWrap)
+        {
+            expectedFileContents.push_back(headerString);
+        }
+
+        if (shouldWrap)
+        {
+            expectedFileContents.push_back(WrapIndicator);
+        }
+        else
+        {
+            expectedFileContents.push_back(largeStringView);
+        }
+
+        expectedFileContents.push_back(largeStringView.substr(0, std::min(largeString.size(), maximumAvailableSpace)));
+
+        ValidateFileContents(tempFile, expectedFileContents, maximumSize);
+    }
+}
+
+TEST_CASE("FileLogger_MaximumSize", "[logging]")
+{
+    auto tagState = GENERATE(TagState_Unset, TagState_SetAtStart, TagState_SetAfterLogging);
+    auto sizeState = GENERATE(MaximumSizeState_Zero, MaximumSizeState_SmallerThanLargeString, MaximumSizeState_EqualToLargeString, MaximumSizeState_SlightlyLargerThanLargeString, MaximumSizeState_MuchLargerThanLargeString);
+    FileLogger_MaximumSize_Test(tagState, sizeState);
+}
+
+TEST_CASE("FileLogger_MaximumSize_ManyWraps", "[logging]")
+{
+    TempFile tempFile{ "FileLogger_ManyWraps", ".log" };
+    FileLogger logger{ tempFile };
+
+    INFO("File: " << tempFile.GetPath().u8string());
+
+    size_t maximumSize = 1000;
+    logger.SetMaximumSize(static_cast<std::ofstream::off_type>(maximumSize));
+
+    std::string header = GetHeaderString();
+    header += " !Now with more header!";
+    std::string largeString = "[*=INIT=*]Now we just need another few dozen characters, which shouldn't be that hard to get. Wow, made it already.";
+    std::string_view largeStringView = largeString;
+    size_t initSize = 10;
+
+    logger.WriteDirect(DefaultChannel, DefaultLevel, header);
+    logger.SetTag(Tag::HeadersComplete);
+
+    // Use the default seed value as we want arbitrary but reproducible results
+    std::default_random_engine randomEngine;
+    std::uniform_int_distribution<> sizeDistribution(static_cast<int>(initSize), 100);
+
+    // We should expect ~500 wraps on average
+    for (size_t i = 0; i < 9999; ++i)
+    {
+        logger.WriteDirect(DefaultChannel, DefaultLevel, largeStringView.substr(0, sizeDistribution(randomEngine)));
+    }
+
+    // We want the header to be preserved, followed by the wrap indicator, and at a minimum we should see the first few characters in the log string
+    std::vector<std::string_view> expectedFileContents;
+    expectedFileContents.push_back(header);
+    expectedFileContents.push_back(WrapIndicator);
+    expectedFileContents.push_back(largeStringView.substr(0, initSize));
+
+    ValidateFileContents(tempFile, expectedFileContents, maximumSize);
+}