diff --git a/README.md b/README.md index c07f9c8..38fd036 100644 --- a/README.md +++ b/README.md @@ -40,12 +40,23 @@ Example of the configuration section in appsettings.json: "Path": "app.log", "Append": true, "MinLevel": "Warning", // min level for the file logger + "IncludeScopes": false, // set to true to include logging scopes "FileSizeLimitBytes": 0, // use to activate rolling file behaviour "MaxRollingFiles": 0 // use to specify max number of log files } } ``` +## Logging scopes +Logging scopes can be included in the default log entry format by setting `FileLoggerOptions.IncludeScopes` to `true` (the default is `false`): +```csharp +loggingBuilder.AddFile("app.log", fileLoggerOpts => { + fileLoggerOpts.IncludeScopes = true; +}); +``` +Active scopes are written from outermost to innermost before the message, for example: `=> Request 123 => Processing order`. +`IncludeScopes` applies only to the built-in formatter and does not change custom `FormatLogEntry` behavior. + ## Rolling File This feature is activated with `FileLoggerOptions` properties: `FileSizeLimitBytes` and `MaxRollingFiles`. Lets assume that file logger is configured for "test.log": diff --git a/src/NReco.Logging.File/FileLogger.cs b/src/NReco.Logging.File/FileLogger.cs index 98fccac..de1cc68 100644 --- a/src/NReco.Logging.File/FileLogger.cs +++ b/src/NReco.Logging.File/FileLogger.cs @@ -30,7 +30,8 @@ public FileLogger(string logName, FileLoggerProvider loggerPrv) { this.LoggerPrv = loggerPrv; } public IDisposable BeginScope(TState state) { - return null; + // Support BeginScope when FileLogger is used directly, matching ConsoleLogger. + return LoggerPrv.ScopeProvider?.Push(state); } public bool IsEnabled(LogLevel logLevel) { @@ -58,6 +59,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, new LogMessage(logName, logLevel, eventId, message, exception))); } else { + // Pass no scope provider unless explicitly enabled so the original formatting path does no scope work. LoggerPrv.WriteEntry( Format.StringLogEntryFormatter.Instance.LowAllocLogEntryFormat( logName, @@ -65,7 +67,8 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, logLevel, eventId, message, - exception)); + exception, + LoggerPrv.Options.IncludeScopes ? LoggerPrv.ScopeProvider : null)); } } diff --git a/src/NReco.Logging.File/FileLoggerConfig.cs b/src/NReco.Logging.File/FileLoggerConfig.cs index c7607d0..d81d254 100644 --- a/src/NReco.Logging.File/FileLoggerConfig.cs +++ b/src/NReco.Logging.File/FileLoggerConfig.cs @@ -50,6 +50,11 @@ public class FileLoggerConfig { /// Minimal logging level for the file logger. /// public LogLevel MinLevel { get; set; } = LogLevel.Trace; + + /// + /// Gets or sets a value that indicates whether scopes are included. Defaults to false. + /// + public bool IncludeScopes { get; set; } } } diff --git a/src/NReco.Logging.File/FileLoggerExtensions.cs b/src/NReco.Logging.File/FileLoggerExtensions.cs index 7358e1f..b21da6c 100644 --- a/src/NReco.Logging.File/FileLoggerExtensions.cs +++ b/src/NReco.Logging.File/FileLoggerExtensions.cs @@ -126,6 +126,7 @@ private static Tuple GetOptionsFromConfiguration(ICon fileLoggerOptions.MinLevel = config.MinLevel; fileLoggerOptions.FileSizeLimitBytes = config.FileSizeLimitBytes; fileLoggerOptions.MaxRollingFiles = config.MaxRollingFiles; + fileLoggerOptions.IncludeScopes = config.IncludeScopes; if (configure != null) configure(fileLoggerOptions); diff --git a/src/NReco.Logging.File/FileLoggerOptions.cs b/src/NReco.Logging.File/FileLoggerOptions.cs index 47dc1d5..d79aa8b 100644 --- a/src/NReco.Logging.File/FileLoggerOptions.cs +++ b/src/NReco.Logging.File/FileLoggerOptions.cs @@ -47,6 +47,12 @@ public class FileLoggerOptions { /// public bool UseUtcTimestamp { get; set; } + /// + /// Gets or sets a value that indicates whether scopes are included. Defaults to false. + /// + /// To preserve the existing API, scopes are included only by the built-in formatter. Custom delegates do not receive scope data. + public bool IncludeScopes { get; set; } + /// /// Custom formatter for the log entry line. /// diff --git a/src/NReco.Logging.File/FileLoggerProvider.cs b/src/NReco.Logging.File/FileLoggerProvider.cs index fd8271c..e92a261 100644 --- a/src/NReco.Logging.File/FileLoggerProvider.cs +++ b/src/NReco.Logging.File/FileLoggerProvider.cs @@ -25,7 +25,7 @@ namespace NReco.Logging.File { /// Generic file logger provider. /// [ProviderAlias("File")] - public class FileLoggerProvider : ILoggerProvider { + public class FileLoggerProvider : ILoggerProvider, ISupportExternalScope { private string LogFileName; @@ -36,6 +36,7 @@ public class FileLoggerProvider : ILoggerProvider { private readonly FileWriter fWriter; internal FileLoggerOptions Options { get; private set; } + internal IExternalScopeProvider ScopeProvider { get; private set; } private bool Append => Options.Append; private long FileSizeLimitBytes => Options.FileSizeLimitBytes; @@ -99,6 +100,12 @@ public ILogger CreateLogger(string categoryName) { return loggers.GetOrAdd(categoryName, CreateLoggerImplementation); } + /// + public void SetScopeProvider(IExternalScopeProvider scopeProvider) { + // Keep this centrally so existing loggers also observe a replacement, matching ConsoleLogger's defensive behavior. + ScopeProvider = scopeProvider; + } + public void Dispose() { entryQueue.CompleteAdding(); try { diff --git a/src/NReco.Logging.File/Format/StringLogEntryFormatter.cs b/src/NReco.Logging.File/Format/StringLogEntryFormatter.cs index 0585c61..dae6ce6 100644 --- a/src/NReco.Logging.File/Format/StringLogEntryFormatter.cs +++ b/src/NReco.Logging.File/Format/StringLogEntryFormatter.cs @@ -1,5 +1,6 @@ using System; using System.Buffers; +using System.Collections.Generic; using System.Runtime.CompilerServices; using System.Text; using Microsoft.Extensions.Logging; @@ -14,6 +15,11 @@ namespace NReco.Logging.File.Format { public class StringLogEntryFormatter { internal static readonly StringLogEntryFormatter Instance = new StringLogEntryFormatter(); + // ForEachScope cannot use the ref-struct ValueStringBuilder as callback state, so scopes are collected into a + // reusable list first and appended to the final ValueStringBuilder directly. This list holds one entry per + // active scope, so its capacity stays as small as the scope nesting and never needs to be trimmed. + [ThreadStatic] + private static List cachedScopes; public StringLogEntryFormatter() { } @@ -64,6 +70,31 @@ public string StringBuilderLogEntryFormat(LogMessage logMsg, DateTime timeStamp) /// This is a low-allocation optimized tab-separated log entry formatter that formats output identical to /// public string LowAllocLogEntryFormat(string logName, DateTime timeStamp, LogLevel logLevel, EventId eventId, string message, Exception exception) { + return LowAllocLogEntryFormatCore(logName, timeStamp, logLevel, eventId, message, exception, null); + } + + internal string LowAllocLogEntryFormat(string logName, DateTime timeStamp, LogLevel logLevel, EventId eventId, string message, Exception exception, IExternalScopeProvider scopeProvider) { + if (scopeProvider == null) { + return LowAllocLogEntryFormatCore(logName, timeStamp, logLevel, eventId, message, exception, null); + } + + var scopes = cachedScopes ?? new List(); + // Check the list out of the cache so re-entrant logging on this thread cannot modify it. + cachedScopes = null; + try { + // Render each scope exactly once. Only the resulting strings are kept, so user scope objects are not + // held alive after the entry is formatted. + scopeProvider.ForEachScope(static (scope, state) => state.Add(scope?.ToString()), scopes); + + return LowAllocLogEntryFormatCore(logName, timeStamp, logLevel, eventId, message, exception, scopes.Count > 0 ? scopes : null); + } finally { + scopes.Clear(); + // Return this list only if a re-entrant log entry has not already replenished the cache. + cachedScopes ??= scopes; + } + } + + private string LowAllocLogEntryFormatCore(string logName, DateTime timeStamp, LogLevel logLevel, EventId eventId, string message, Exception exception, List scopes) { const int MaxStackAllocatedBufferLength = 256; var logMessageLength = CalculateLogMessageLength(); char[] charBuffer = null; @@ -74,7 +105,8 @@ public string LowAllocLogEntryFormat(string logName, DateTime timeStamp, LogLeve // default formatting logic using var logBuilder = new ValueStringBuilder(buffer); - if (!string.IsNullOrEmpty(message)) { + // Scopes are useful context even when an exception is logged without a message. + if (!string.IsNullOrEmpty(message) || scopes != null) { timeStamp.TryFormatO(logBuilder.RemainingRawChars, out var charsWritten); logBuilder.AppendSpan(charsWritten); logBuilder.Append('\t'); @@ -90,7 +122,17 @@ public string LowAllocLogEntryFormat(string logName, DateTime timeStamp, LogLeve logBuilder.AppendSpan(charsWritten); } logBuilder.Append("]\t"); - logBuilder.Append(message); + if (scopes != null) { + // Match SimpleConsoleFormatter: render active scopes outer-to-inner with "=>" separators. + for (var i = 0; i < scopes.Count; i++) { + logBuilder.Append(i == 0 ? "=> " : " => "); + logBuilder.Append(scopes[i]); + } + logBuilder.Append('\t'); + } + if (!string.IsNullOrEmpty(message)) { + logBuilder.Append(message); + } } if (exception != null) { @@ -114,8 +156,21 @@ int CalculateLogMessageLength() { + 3 /* "]\t[" */ + (eventId.Name?.Length ?? eventId.Id.GetFormattedLength()) + 2 /* "]\t" */ + + GetScopesLength() + (message?.Length ?? 0); } + + int GetScopesLength() { + if (scopes is null) { + return 0; + } + + var scopesLength = 1 /* '\t' */; + for (var i = 0; i < scopes.Count; i++) { + scopesLength += (i == 0 ? 3 /* "=> " */ : 4 /* " => " */) + (scopes[i]?.Length ?? 0); + } + return scopesLength; + } } public string LowAllocLogEntryFormat(LogMessage logMsg, DateTime timeStamp) diff --git a/test/NReco.Logging.Tests/FileProviderTests.cs b/test/NReco.Logging.Tests/FileProviderTests.cs index fcad93a..1df022d 100644 --- a/test/NReco.Logging.Tests/FileProviderTests.cs +++ b/test/NReco.Logging.Tests/FileProviderTests.cs @@ -517,5 +517,102 @@ public void CustomFilterLogEntry() { } } + [Fact] + public void ScopesAreDisabledByDefault() { + var tmpFile = Path.GetTempFileName(); + try { + using (var factory = new LoggerFactory()) { + factory.AddProvider(new FileLoggerProvider(tmpFile, false)); + var logger = factory.CreateLogger("TEST"); + using (logger.BeginScope("Scope")) { + logger.LogInformation("Message"); + } + } + + var logEntry = System.IO.File.ReadAllText(tmpFile); + // Scopes should not appear unless they are explicitly enabled. + Assert.DoesNotContain("Scope", logEntry); + Assert.Contains("\tMessage", logEntry); + } finally { + System.IO.File.Delete(tmpFile); + } + } + + [Fact] + public void WriteNestedScopesInOuterToInnerOrder() { + var tmpFile = Path.GetTempFileName(); + try { + using (var factory = new LoggerFactory()) { + factory.AddProvider(new FileLoggerProvider(tmpFile, new FileLoggerOptions() { + Append = false, + IncludeScopes = true + })); + var logger = factory.CreateLogger("TEST"); + using (logger.BeginScope("Outer")) { + using (logger.BeginScope("Inner")) { + logger.LogInformation("Nested"); + } + logger.LogInformation("Outer only"); + } + logger.LogInformation("No scope"); + } + + var logEntries = System.IO.File.ReadAllLines(tmpFile); + // Disposing the inner scope should leave the outer scope active; disposing both should leave neither. + Assert.Equal("=> Outer => Inner", logEntries[0].Split('\t')[4]); + Assert.Equal("Nested", logEntries[0].Split('\t')[5]); + + Assert.Equal("=> Outer", logEntries[1].Split('\t')[4]); + Assert.Equal("Outer only", logEntries[1].Split('\t')[5]); + + Assert.Equal("No scope", logEntries[2].Split('\t')[4]); + } finally { + System.IO.File.Delete(tmpFile); + } + } + + [Fact] + public void LoggerCreatedBeforeScopeProviderUsesScopes() { + var tmpFile = Path.GetTempFileName(); + try { + using (var provider = new FileLoggerProvider(tmpFile, new FileLoggerOptions() { + Append = false, + IncludeScopes = true + })) { + var logger = provider.CreateLogger("TEST"); + provider.SetScopeProvider(new LoggerExternalScopeProvider()); + using (logger.BeginScope("Scope")) { + logger.LogInformation("Message"); + } + } + + // A logger created before SetScopeProvider should use the provider assigned later. + Assert.Contains("\t=> Scope\tMessage", System.IO.File.ReadAllText(tmpFile)); + } finally { + System.IO.File.Delete(tmpFile); + } + } + + [Fact] + public void CustomFormatLogEntryIgnoresScopes() { + var tmpFile = Path.GetTempFileName(); + try { + using (var factory = new LoggerFactory()) { + factory.AddProvider(new FileLoggerProvider(tmpFile, new FileLoggerOptions() { + Append = false, + IncludeScopes = true, + FormatLogEntry = logMessage => $"Custom: {logMessage.Message}" + })); + var logger = factory.CreateLogger("TEST"); + using (logger.BeginScope("Scope")) { + logger.LogInformation("Message"); + } + } + + Assert.Equal($"Custom: Message{Environment.NewLine}", System.IO.File.ReadAllText(tmpFile)); + } finally { + System.IO.File.Delete(tmpFile); + } + } } } diff --git a/test/NReco.Logging.Tests/StringLogEntryFormatterTests.cs b/test/NReco.Logging.Tests/StringLogEntryFormatterTests.cs index 0f2dae3..da9460f 100644 --- a/test/NReco.Logging.Tests/StringLogEntryFormatterTests.cs +++ b/test/NReco.Logging.Tests/StringLogEntryFormatterTests.cs @@ -35,6 +35,95 @@ public void LowAllocLogEntryFormatVeryLongMessage() { LowAllocLogEntryFormat("aaa", LogLevel.Trace, 0, String.Concat(Enumerable.Repeat("TestValue ", 1000)), "test"); } + [Fact] + public void LowAllocLogEntryFormatScopes() { + var formatter = StringLogEntryFormatter.Instance; + var scopeProvider = new LoggerExternalScopeProvider(); + var dt = DateTime.UtcNow; + using (scopeProvider.Push("Outer")) + using (scopeProvider.Push("Inner")) { + var result = formatter.LowAllocLogEntryFormat("test", dt, LogLevel.Information, new EventId(7), "Message", null, scopeProvider); + + // Nested scopes should render outer-to-inner immediately before the message. + Assert.Equal($"{dt:o}\tINFO\t[test]\t[7]\t=> Outer => Inner\tMessage", result); + } + } + + [Fact] + public void LowAllocLogEntryFormatNoActiveScopes() { + var formatter = StringLogEntryFormatter.Instance; + var scopeProvider = new LoggerExternalScopeProvider(); + var dt = DateTime.UtcNow; + + var result = formatter.LowAllocLogEntryFormat("test", dt, LogLevel.Information, new EventId(7), "Message", null, scopeProvider); + + // With no active scopes, the output should match the original formatter output. + Assert.Equal(formatter.LowAllocLogEntryFormat("test", dt, LogLevel.Information, new EventId(7), "Message", null), result); + } + + [Fact] + public void LowAllocLogEntryFormatExceptionOnlyIncludesScopes() { + var formatter = StringLogEntryFormatter.Instance; + var scopeProvider = new LoggerExternalScopeProvider(); + var dt = DateTime.UtcNow; + var exception = new InvalidOperationException("Error"); + using (scopeProvider.Push("Scope")) { + var result = formatter.LowAllocLogEntryFormat("test", dt, LogLevel.Error, new EventId(7), null, exception, scopeProvider); + + // An exception-only entry should still include its active scope. + Assert.Equal($"{dt:o}\tFAIL\t[test]\t[7]\t=> Scope\t{exception}{Environment.NewLine}", result); + } + } + + [Fact] + public void LowAllocLogEntryFormatExceptionOnlyWithoutActiveScopes() { + var formatter = StringLogEntryFormatter.Instance; + var scopeProvider = new LoggerExternalScopeProvider(); + var dt = DateTime.UtcNow; + var exception = new InvalidOperationException("Error"); + + var result = formatter.LowAllocLogEntryFormat("test", dt, LogLevel.Error, new EventId(7), null, exception, scopeProvider); + + Assert.Equal(formatter.LowAllocLogEntryFormat("test", dt, LogLevel.Error, new EventId(7), null, exception), result); + } + + [Fact] + public void LowAllocLogEntryFormatReentrantScopeToString() { + var formatter = StringLogEntryFormatter.Instance; + var scopeProvider = new LoggerExternalScopeProvider(); + var dt = DateTime.UtcNow; + string innerResult = null; + var scope = new ReentrantScope("Scope", onFirstToString: () => { + // Appending a scope calls its user-defined ToString(), which may itself log. + // Simulate that by formatting another entry before the outer call has finished. + innerResult = formatter.LowAllocLogEntryFormat("test", dt, LogLevel.Information, new EventId(7), "Inner", null, scopeProvider); + }); + + string outerResult; + using (scopeProvider.Push(scope)) { + outerResult = formatter.LowAllocLogEntryFormat("test", dt, LogLevel.Information, new EventId(7), "Outer", null, scopeProvider); + } + + // Despite both calls running on the same thread, each must retain its own scopes and message. + Assert.Equal($"{dt:o}\tINFO\t[test]\t[7]\t=> Scope\tInner", innerResult); + Assert.Equal($"{dt:o}\tINFO\t[test]\t[7]\t=> Scope\tOuter", outerResult); + } + + [Fact] + public void LowAllocLogEntryFormatLongAndNullScopes() { + var formatter = StringLogEntryFormatter.Instance; + var scopeProvider = new LoggerExternalScopeProvider(); + var dt = DateTime.UtcNow; + var longScope = String.Concat(Enumerable.Repeat("Scope", 1000)); + using (scopeProvider.Push(null)) + using (scopeProvider.Push(longScope)) { + var result = formatter.LowAllocLogEntryFormat("test", dt, LogLevel.Information, new EventId(7), "Message", null, scopeProvider); + + // Null scopes should render consistently, and long scopes should not be truncated. + Assert.Equal($"{dt:o}\tINFO\t[test]\t[7]\t=> => {longScope}\tMessage", result); + } + } + [Fact] public void GetFormattedLengthOfZero() { @@ -226,6 +315,24 @@ public void DateTimeTryFormatIntoTooShortSpan() { Assert.True(span.SequenceEqual(expected)); } + private sealed class ReentrantScope { + private readonly string value; + private readonly Action onFirstToString; + private bool hasFormatted; + + public ReentrantScope(string value, Action onFirstToString) { + this.value = value; + this.onFirstToString = onFirstToString; + } + + public override string ToString() { + if (!hasFormatted) { + hasFormatted = true; + onFirstToString(); + } + return value; + } + } } }