Add FileAppend feature to the Logging module

.gitignore

@@ -62,3 +62,5 @@ nunit-*.xml
 
 # Temporary BenchmarkDotNet output from older runs
 /reports/DependencyInjection/raw/
+/.vs
+*.user

metadata/Logging/features.json

@@ -48,6 +48,12 @@
       "order": 8,
       "name": "Prepare Logger",
       "description": "Creates, verifies, and releases one Information-enabled logger with an in-memory sink."
+    },
+    {
+      "id": "FileAppend",
+      "order": 9,
+      "name": "File Append",
+      "description": "Appends one event to an already open file with buffering enabled and no flush per event."
     }
   ]
 }

src/Matrix.Logging/Benchmarks/Common/09_FileAppend.cs

@@ -0,0 +1,47 @@
+namespace Matrix.Logging.Benchmarks;
+
+[MemoryDiagnoser]
+[Orderer(SummaryOrderPolicy.FastestToSlowest)]
+[FeatureUnavailable(
+    LibraryCatalog.MicrosoftExtensionsLogging,
+    FeatureStatus.Unsupported,
+    "Microsoft.Extensions.Logging defines no file provider in the core package.")]
+[MatrixFeature(
+    "FileAppend",
+    9,
+    "File Append",
+    "Appends one event to an already open file with buffering enabled and no flush per event.")]
+public partial class FileAppend
+{
+    private static readonly string _workDirectory =
+        Path.Combine(Path.GetTempPath(), "matrix-logging-fileappend");
+
+    private static string CreateFilePath(string library)
+    {
+        Directory.CreateDirectory(_workDirectory);
+        return Path.Combine(_workDirectory, $"{library}.{Guid.NewGuid():N}.log");
+    }
+
+    /// <summary>
+    /// Reads the file back once every arm has closed its writer, so delivery is validated against
+    /// what actually reached the disk rather than against an in-memory sink.
+    /// </summary>
+    private static void Verify(string library, string path)
+    {
+        string[] lines = File.Exists(path) ? File.ReadAllLines(path) : [];
+        LoggingChecks.FileAppended(
+            library,
+            lines.Length,
+            lines.Length == 0 ? null : lines[^1]);
+
+        try
+        {
+            File.Delete(path);
+        }
+        catch (IOException)
+        {
+            // Each arm closes its writer before this runs, so this is unexpected - but a leftover
+            // file in the temp directory is not worth failing a benchmark over.
+        }
+    }
+}

src/Matrix.Logging/Benchmarks/Log4Net/03_StructuredProperties.cs

@@ -18,8 +18,13 @@ public partial class StructuredProperties
     [LibraryBenchmark(LibraryCatalog.Log4Net)]
     public void Log4Net()
     {
-        LogicalThreadContext.Properties["OrderId"] = LoggingData.OrderId;
-        LogicalThreadContext.Properties["ElapsedMs"] = LoggingData.ElapsedMs;
+        // ThreadContext rather than LogicalThreadContext: the other arms of this feature pass
+        // structured parameters straight to the logger and use no ambient context at all, so the
+        // async-flow-safe variant would charge log4net for propagation nobody else pays for. The
+        // ScopeOrContext feature is where async-safe context belongs, and it still uses
+        // LogicalThreadContext there, matching Serilog's LogContext.
+        ThreadContext.Properties["OrderId"] = LoggingData.OrderId;
+        ThreadContext.Properties["ElapsedMs"] = LoggingData.ElapsedMs;
         try
         {
             _log4Net.Logger.InfoFormat(
@@ -30,8 +35,8 @@ public void Log4Net()
         }
         finally
         {
-            LogicalThreadContext.Properties.Remove("OrderId");
-            LogicalThreadContext.Properties.Remove("ElapsedMs");
+            ThreadContext.Properties.Remove("OrderId");
+            ThreadContext.Properties.Remove("ElapsedMs");
         }
 
         LoggingChecks.Structured(LibraryCatalog.Log4Net, _log4Net.Sink.Last);

src/Matrix.Logging/Benchmarks/Log4Net/09_FileAppend.cs

@@ -0,0 +1,48 @@
+using log4net;
+using log4net.Appender;
+using log4net.Config;
+using log4net.Core;
+using log4net.Layout;
+using log4net.Repository.Hierarchy;
+
+namespace Matrix.Logging.Benchmarks;
+
+public partial class FileAppend
+{
+    private string _log4NetPath = null!;
+    private string _log4NetRepository = null!;
+    private FileAppender _log4NetAppender = null!;
+    private ILog _log4NetLogger = null!;
+
+    [GlobalSetup(Target = nameof(Log4Net))]
+    public void SetupLog4Net()
+    {
+        _log4NetPath = CreateFilePath(LibraryCatalog.Log4Net);
+        _log4NetRepository = $"{LoggingData.Category}.{Guid.NewGuid():N}";
+        var repository = (Hierarchy)LogManager.CreateRepository(_log4NetRepository);
+        _log4NetAppender = new FileAppender
+        {
+            File = _log4NetPath,
+            AppendToFile = true,
+            ImmediateFlush = false,
+            Layout = new PatternLayout(LoggingData.Log4NetFileLayout)
+        };
+        _log4NetAppender.ActivateOptions();
+        BasicConfigurator.Configure(repository, _log4NetAppender);
+        repository.Root.Level = Level.Info;
+        repository.Configured = true;
+        _log4NetLogger = LogManager.GetLogger(_log4NetRepository, LoggingData.Category);
+    }
+
+    [GlobalCleanup(Target = nameof(Log4Net))]
+    public void CleanupLog4Net()
+    {
+        _log4NetAppender.Close();
+        LogManager.ShutdownRepository(_log4NetRepository);
+        Verify(LibraryCatalog.Log4Net, _log4NetPath);
+    }
+
+    [Benchmark]
+    [LibraryBenchmark(LibraryCatalog.Log4Net)]
+    public void Log4Net() => _log4NetLogger.Info(LoggingData.FileMessage);
+}

src/Matrix.Logging/Benchmarks/NLog/09_FileAppend.cs

@@ -0,0 +1,42 @@
+using NLog;
+using NLog.Config;
+using NLog.Targets;
+
+namespace Matrix.Logging.Benchmarks;
+
+public partial class FileAppend
+{
+    private string _nlogPath = null!;
+    private LogFactory _nlogFactory = null!;
+    private Logger _nlogLogger = null!;
+
+    [GlobalSetup(Target = nameof(NLog))]
+    public void SetupNLog()
+    {
+        _nlogPath = CreateFilePath(LibraryCatalog.NLog);
+        var target = new FileTarget
+        {
+            FileName = _nlogPath,
+            KeepFileOpen = true,
+            AutoFlush = false,
+            Layout = LoggingData.NLogFileLayout
+        };
+        var configuration = new LoggingConfiguration();
+        configuration.AddRule(LogLevel.Info, LogLevel.Fatal, target, LoggingData.Category);
+        _nlogFactory = new LogFactory { Configuration = configuration };
+        _nlogLogger = _nlogFactory.GetLogger(LoggingData.Category);
+    }
+
+    [GlobalCleanup(Target = nameof(NLog))]
+    public void CleanupNLog()
+    {
+        _nlogFactory.Flush(TimeSpan.FromSeconds(5));
+        _nlogFactory.Shutdown();
+        _nlogFactory.Dispose();
+        Verify(LibraryCatalog.NLog, _nlogPath);
+    }
+
+    [Benchmark]
+    [LibraryBenchmark(LibraryCatalog.NLog)]
+    public void NLog() => _nlogLogger.Info(LoggingData.FileMessage);
+}

src/Matrix.Logging/Benchmarks/Serilog/09_FileAppend.cs

@@ -0,0 +1,36 @@
+using Serilog;
+using Serilog.Events;
+
+namespace Matrix.Logging.Benchmarks;
+
+public partial class FileAppend
+{
+    private string _serilogPath = null!;
+    private Serilog.Core.Logger _serilogRoot = null!;
+    private Serilog.ILogger _serilogLogger = null!;
+
+    [GlobalSetup(Target = nameof(Serilog))]
+    public void SetupSerilog()
+    {
+        _serilogPath = CreateFilePath(LibraryCatalog.Serilog);
+        _serilogRoot = new LoggerConfiguration()
+            .MinimumLevel.Is(LogEventLevel.Information)
+            .WriteTo.File(
+                _serilogPath,
+                buffered: true,
+                outputTemplate: LoggingData.SerilogFileTemplate)
+            .CreateLogger();
+        _serilogLogger = _serilogRoot.ForContext("SourceContext", LoggingData.Category);
+    }
+
+    [GlobalCleanup(Target = nameof(Serilog))]
+    public void CleanupSerilog()
+    {
+        _serilogRoot.Dispose();
+        Verify(LibraryCatalog.Serilog, _serilogPath);
+    }
+
+    [Benchmark]
+    [LibraryBenchmark(LibraryCatalog.Serilog)]
+    public void Serilog() => _serilogLogger.Information(LoggingData.FileMessage);
+}

src/Matrix.Logging/Benchmarks/ZLogger/09_FileAppend.cs

@@ -0,0 +1,40 @@
+using Microsoft.Extensions.Logging;
+using ZLogger;
+
+namespace Matrix.Logging.Benchmarks;
+
+public partial class FileAppend
+{
+    private string _zloggerPath = null!;
+    private ILoggerFactory _zloggerFactory = null!;
+    private ILogger _zloggerLogger = null!;
+
+    [GlobalSetup(Target = nameof(ZLogger))]
+    public void SetupZLogger()
+    {
+        _zloggerPath = CreateFilePath(LibraryCatalog.ZLogger);
+        _zloggerFactory = LoggerFactory.Create(builder =>
+        {
+            builder.ClearProviders();
+            builder.SetMinimumLevel(LogLevel.Information);
+            builder.AddZLoggerFile(_zloggerPath, options => options.UsePlainTextFormatter(formatter =>
+                formatter.SetPrefixFormatter(
+                    $"{0:yyyy-MM-dd HH:mm:ss,fff} {1:short} {2} - ",
+                    (in MessageTemplate template, in LogInfo info) =>
+                        template.Format(info.Timestamp.Local.DateTime, info.LogLevel, info.Category))));
+        });
+        _zloggerLogger = _zloggerFactory.CreateLogger(LoggingData.Category);
+    }
+
+    [GlobalCleanup(Target = nameof(ZLogger))]
+    public void CleanupZLogger()
+    {
+        // Disposing the factory drains the background queue and closes the file.
+        _zloggerFactory.Dispose();
+        Verify(LibraryCatalog.ZLogger, _zloggerPath);
+    }
+
+    [Benchmark]
+    [LibraryBenchmark(LibraryCatalog.ZLogger)]
+    public void ZLogger() => _zloggerLogger.LogInformation(LoggingData.FileMessage);
+}

src/Matrix.Logging/Log4NetFixture.cs

@@ -14,15 +14,22 @@ public Log4NetFixture(Level minimumLevel, bool buffered = false)
     {
         var repositoryName = $"{LoggingData.Category}.{Guid.NewGuid():N}";
         Repository = (Hierarchy)LogManager.CreateRepository(repositoryName);
-        Sink = new Log4NetCaptureAppender();
+        Sink = new();
         Sink.ActivateOptions();
         IAppender appender = Sink;
         if (buffered)
         {
-            _buffer = new BufferingForwardingAppender
+            _buffer = new()
             {
                 BufferSize = 100,
-                Lossy = false
+                Lossy = false,
+                // log4net defaults to FixFlags.All, which captures caller location (a stack walk)
+                // and the Windows identity (a local security authority lookup) for every buffered
+                // event. NLog's AsyncTargetWrapper and Serilog's WriteTo.Async capture neither, so
+                // the default would charge log4net for work the other arms never do. Partial is the
+                // set log4net's own FixFlags documentation recommends for performance, and it still
+                // fixes everything this feature validates: message, level, exception and properties.
+                Fix = FixFlags.Partial
             };
             _buffer.AddAppender(Sink);
             _buffer.ActivateOptions();

src/Matrix.Logging/LoggingChecks.cs

@@ -53,6 +53,19 @@ public static void Buffered(string library, int count, CapturedLogEvent? actual)
         RequireEvent(library, actual, "Information", LoggingData.BufferedMessage);
     }
 
+    [Conditional("MATRIX_VALIDATION")]
+    public static void FileAppended(string library, int lineCount, string? lastLine)
+    {
+        MatrixValidation.Require(
+            library,
+            lineCount == 3,
+            $"Expected 3 appended lines, found {lineCount}.");
+        MatrixValidation.Require(
+            library,
+            lastLine is not null && lastLine.EndsWith(LoggingData.FileMessage, StringComparison.Ordinal),
+            $"Last appended line does not end with '{LoggingData.FileMessage}': '{lastLine}'.");
+    }
+
     [Conditional("MATRIX_VALIDATION")]
     public static void Prepared(string library, bool informationEnabled) =>
         MatrixValidation.Require(

src/Matrix.Logging/LoggingData.cs

@@ -16,5 +16,12 @@ internal static class LoggingData
     public const decimal Amount = 12.5m;
     public const string Customer = "Ada";
     public const string BufferedMessage = "Buffered event";
-}
+    public const string FileMessage = "Persisted event";
 
+    // Equivalent plain text layouts for the FileAppend feature: timestamp, padded level, logger
+    // name and message. Keeping the rendered width comparable keeps the measured write comparable.
+    public const string Log4NetFileLayout = "%date %-5level %logger - %message%newline";
+    public const string NLogFileLayout = "${longdate} ${level:uppercase=true:padding=-5} ${logger} - ${message}";
+    public const string SerilogFileTemplate =
+        "{Timestamp:yyyy-MM-dd HH:mm:ss,fff} {Level:u5} {SourceContext} - {Message}{NewLine}";
+}

src/Matrix.Logging/Matrix.Logging.csproj

@@ -41,6 +41,7 @@
             <MatrixLogo>logos/serilog.svg</MatrixLogo>
         </PackageReference>
         <PackageReference Include="Serilog.Sinks.Async" Version="2.1.0"/>
+        <PackageReference Include="Serilog.Sinks.File" Version="7.0.0"/>
         <PackageReference Include="NLog" Version="6.1.4">
             <MatrixLibraryId>NLog</MatrixLibraryId>
             <MatrixLibraryName>NLog</MatrixLibraryName>