From 6d8e6a90b746577fef62848fc36d612893ff3888 Mon Sep 17 00:00:00 2001 From: Evgenii Fedorov Date: Wed, 7 Oct 2026 14:16:54 +0200 Subject: [PATCH] Optionally preserve logging scopes in buffered log records Adds the experimental GlobalLogBufferingOptions.IncludeScopes and PerRequestLogBufferingOptions.IncludeScopes options (EXTEXP0003). When an option is enabled, the buffer adds the name/value pairs of the logging scopes that are active when a log record is buffered to the record's attributes. IBufferedLogger implementations get them in BufferedLogRecord.Attributes, and other loggers get them in the state passed to ILogger.Log. - Only scopes that implement IEnumerable> are added, without their "{OriginalFormat}" pairs. The log record's own "{OriginalFormat}" stays the last attribute. - Scope values are converted to strings and count toward the size limits. - The buffers get the IExternalScopeProvider through constructor injection. AddGlobalBuffer registers one with TryAddSingleton, and ExtendedLoggerFactory uses it too, so the factory and the buffers share it. - Both options bind from configuration, and the delegate overload of AddPerIncomingRequestBuffer copies IncludeScopes to the global buffer options. Fixes #7781 Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- .../Buffering/IncomingRequestLogBuffer.cs | 9 +- ...IncomingRequestLoggingBuilderExtensions.cs | 6 +- .../Buffering/PerRequestLogBufferManager.cs | 8 +- .../PerRequestLogBufferingConfigureOptions.cs | 1 + .../PerRequestLogBufferingOptions.cs | 12 ++ ...oft.AspNetCore.Diagnostics.Middleware.json | 4 + .../README.md | 2 + .../Buffering/GlobalBuffer.cs | 9 +- .../GlobalBufferLoggingBuilderExtensions.cs | 3 + .../Buffering/GlobalLogBufferManager.cs | 18 +- .../GlobalLogBufferingConfigureOptions.cs | 1 + .../Buffering/GlobalLogBufferingOptions.cs | 12 ++ .../Microsoft.Extensions.Telemetry.json | 4 + .../Microsoft.Extensions.Telemetry/README.md | 4 +- .../SerializedLogRecordFactory.cs | 61 +++++- ...ingRequestLoggingBuilderExtensionsTests.cs | 10 + ...erRequestLogBufferingIncludeScopesTests.cs | 61 ++++++ ...ogBufferingOptionsConfigureOptionsTests.cs | 2 + .../GlobalBufferIncludeScopesTests.cs | 173 ++++++++++++++++++ ...GlobalLogBufferingConfigureOptionsTests.cs | 2 + 20 files changed, 387 insertions(+), 15 deletions(-) create mode 100644 test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingIncludeScopesTests.cs create mode 100644 test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferIncludeScopesTests.cs diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBuffer.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBuffer.cs index 26deeb22e9a..a0738ea0920 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBuffer.cs +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBuffer.cs @@ -8,6 +8,7 @@ using System.Linq; using System.Threading; using Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.ObjectPool; using Microsoft.Extensions.Options; @@ -23,6 +24,7 @@ internal sealed class IncomingRequestLogBuffer PoolFactory.CreateListPoolWithCapacity(MaxBatchSize); private readonly IBufferedLogger _bufferedLogger; + private readonly IExternalScopeProvider _scopeProvider; private readonly IOptionsMonitor _options; private readonly TimeProvider _timeProvider = TimeProvider.System; private readonly LogBufferingFilterRule[] _filterRules; @@ -35,9 +37,11 @@ internal sealed class IncomingRequestLogBuffer public IncomingRequestLogBuffer( IBufferedLogger bufferedLogger, string category, - IOptionsMonitor options) + IOptionsMonitor options, + IExternalScopeProvider scopeProvider) { _bufferedLogger = bufferedLogger; + _scopeProvider = scopeProvider; _options = options; _filterRules = LogBufferingFilterRuleSelector.SelectByCategory(_options.CurrentValue.Rules.ToArray(), category); } @@ -72,7 +76,8 @@ public bool TryEnqueue(LogEntry logEntry) _timeProvider.GetUtcNow(), attributes, logEntry.Exception, - logEntry.Formatter(logEntry.State, logEntry.Exception)); + logEntry.Formatter(logEntry.State, logEntry.Exception), + _options.CurrentValue.IncludeScopes ? _scopeProvider : null); if (serializedLogRecord.SizeInBytes > _options.CurrentValue.MaxLogRecordSizeInBytes) { diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerIncomingRequestLoggingBuilderExtensions.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerIncomingRequestLoggingBuilderExtensions.cs index 840fc80c6cd..28ad6ee116d 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerIncomingRequestLoggingBuilderExtensions.cs +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerIncomingRequestLoggingBuilderExtensions.cs @@ -74,7 +74,11 @@ public static ILoggingBuilder AddPerIncomingRequestBuffer(this ILoggingBuilder b return builder .AddPerRequestBufferManager() - .AddGlobalBuffer(opts => opts.Rules = options.Rules); + .AddGlobalBuffer(opts => + { + opts.Rules = options.Rules; + opts.IncludeScopes = options.IncludeScopes; + }); } /// diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferManager.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferManager.cs index bc6abad78b9..b431e54e56d 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferManager.cs +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferManager.cs @@ -5,6 +5,7 @@ using Microsoft.AspNetCore.Http; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Options; @@ -16,15 +17,18 @@ internal sealed class PerRequestLogBufferManager : PerRequestLogBuffer private readonly GlobalLogBuffer _globalBuffer; private readonly IHttpContextAccessor _httpContextAccessor; + private readonly IExternalScopeProvider _scopeProvider; public PerRequestLogBufferManager( GlobalLogBuffer globalBuffer, IHttpContextAccessor httpContextAccessor, - IOptionsMonitor options) + IOptionsMonitor options, + IExternalScopeProvider scopeProvider) { _globalBuffer = globalBuffer; _httpContextAccessor = httpContextAccessor; Options = options; + _scopeProvider = scopeProvider; } public override void Flush() @@ -45,7 +49,7 @@ public override bool TryEnqueue(IBufferedLogger bufferedLogger, in LogEn IncomingRequestLogBufferHolder? bufferHolder = httpContext.RequestServices?.GetService(); IncomingRequestLogBuffer? buffer = bufferHolder?.GetOrAdd(category, _ => - new IncomingRequestLogBuffer(bufferedLogger, category, Options)); + new IncomingRequestLogBuffer(bufferedLogger, category, Options, _scopeProvider)); if (buffer is null) { diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingConfigureOptions.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingConfigureOptions.cs index 54e1e2dc674..e0160a9455a 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingConfigureOptions.cs +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingConfigureOptions.cs @@ -39,6 +39,7 @@ public void Configure(PerRequestLogBufferingOptions options) options.MaxLogRecordSizeInBytes = parsedOptions.MaxLogRecordSizeInBytes; options.MaxPerRequestBufferSizeInBytes = parsedOptions.MaxPerRequestBufferSizeInBytes; options.AutoFlushDuration = parsedOptions.AutoFlushDuration; + options.IncludeScopes = parsedOptions.IncludeScopes; foreach (LogBufferingFilterRule rule in parsedOptions.Rules) { diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptions.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptions.cs index 5e0cc99f779..e705f2baeb1 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptions.cs +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptions.cs @@ -5,8 +5,10 @@ using System; using System.Collections.Generic; using System.ComponentModel.DataAnnotations; +using System.Diagnostics.CodeAnalysis; using Microsoft.Extensions.Diagnostics.Buffering; using Microsoft.Shared.Data.Validation; +using Microsoft.Shared.DiagnosticIds; namespace Microsoft.AspNetCore.Diagnostics.Buffering; @@ -58,6 +60,16 @@ public class PerRequestLogBufferingOptions [Range(MinimumPerRequestBufferSizeInBytes, MaximumPerRequestBufferSizeInBytes)] public int MaxPerRequestBufferSizeInBytes { get; set; } = DefaultPerRequestBufferSizeInBytes; + /// + /// Gets or sets a value indicating whether logging scopes are added to the attributes of log records when they're buffered. + /// + /// + /// Only scopes that implement IEnumerable<KeyValuePair<string, object?>> are added, without their "{OriginalFormat}" pairs. + /// Scope values are converted to strings and count toward and . + /// + [Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] + public bool IncludeScopes { get; set; } + /// /// Gets or sets the collection of used for filtering log messages for the purpose of further buffering. /// diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Microsoft.AspNetCore.Diagnostics.Middleware.json b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Microsoft.AspNetCore.Diagnostics.Middleware.json index 4d1faa80db7..9b651241c1d 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Microsoft.AspNetCore.Diagnostics.Middleware.json +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Microsoft.AspNetCore.Diagnostics.Middleware.json @@ -184,6 +184,10 @@ "Member": "System.TimeSpan Microsoft.AspNetCore.Diagnostics.Buffering.PerRequestLogBufferingOptions.AutoFlushDuration { get; set; }", "Stage": "Stable" }, + { + "Member": "bool Microsoft.AspNetCore.Diagnostics.Buffering.PerRequestLogBufferingOptions.IncludeScopes { get; set; }", + "Stage": "Experimental" + }, { "Member": "int Microsoft.AspNetCore.Diagnostics.Buffering.PerRequestLogBufferingOptions.MaxLogRecordSizeInBytes { get; set; }", "Stage": "Stable" diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/README.md b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/README.md index c6190f0ab67..873409d60ef 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/README.md +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/README.md @@ -74,6 +74,8 @@ public class MyService Per-request buffering is especially useful for capturing all logs related to a specific HTTP request and making decisions about them collectively based on request outcomes. Per-request buffering is tightly coupled with [Global Buffering](https://github.com/dotnet/extensions/blob/main/src/Libraries/Microsoft.Extensions.Telemetry/README.md#log-buffering). If a log entry is supposed to be buffered to a per-request buffer, but there is no active HTTP context, it will be buffered to the global buffer instead. If buffer flush is triggered, the per-request buffer will be flushed first, followed by the global buffer. +To preserve logging scopes in buffered log records, set the experimental `IncludeScopes` option, which adds the scopes' name/value pairs to the records' attributes. + ### Tracking HTTP Request Latency These components enable tracking and reporting the latency of HTTP request processing. diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs index 825404a0ae1..a4e666de19e 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs @@ -7,6 +7,7 @@ using System.Collections.Generic; using System.Linq; using System.Threading; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.ObjectPool; using Microsoft.Extensions.Options; @@ -25,6 +26,7 @@ internal sealed class GlobalBuffer : IDisposable private readonly IOptionsMonitor _options; private readonly IBufferedLogger _bufferedLogger; + private readonly IExternalScopeProvider _scopeProvider; private readonly TimeProvider _timeProvider; private readonly IDisposable? _optionsChangeTokenRegistration; private readonly string _category; @@ -42,11 +44,13 @@ public GlobalBuffer( IBufferedLogger bufferedLogger, string category, IOptionsMonitor options, - TimeProvider timeProvider) + TimeProvider timeProvider, + IExternalScopeProvider scopeProvider) { _options = Throw.IfNull(options); _timeProvider = timeProvider; _bufferedLogger = bufferedLogger; + _scopeProvider = scopeProvider; _category = Throw.IfNullOrEmpty(category); LastKnownGoodFilterRules = LogBufferingFilterRuleSelector.SelectByCategory(_options.CurrentValue.Rules.ToArray(), _category); _optionsChangeTokenRegistration = options.OnChange(OnOptionsChanged); @@ -94,7 +98,8 @@ public bool TryEnqueue(LogEntry logEntry) _timeProvider.GetUtcNow(), attributes, logEntry.Exception, - logEntry.Formatter(logEntry.State, logEntry.Exception)); + logEntry.Formatter(logEntry.State, logEntry.Exception), + _options.CurrentValue.IncludeScopes ? _scopeProvider : null); if (serializedLogRecord.SizeInBytes > _options.CurrentValue.MaxLogRecordSizeInBytes) { diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggingBuilderExtensions.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggingBuilderExtensions.cs index fe5ca3b5d22..58cef54f3a5 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggingBuilderExtensions.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggingBuilderExtensions.cs @@ -92,6 +92,9 @@ private static ILoggingBuilder AddGlobalBufferManager(this ILoggingBuilder build { _ = builder.Services.AddExtendedLoggerFeactory(); + builder.Services.TryAddSingleton(static sp => + new LoggerFactoryScopeProvider(sp.GetRequiredService>().Value.ActivityTrackingOptions)); + builder.Services.TryAddSingleton(); builder.Services.TryAddSingleton(static sp => sp.GetRequiredService()); builder.Services.TryAddSingleton(static sp => sp.GetRequiredService()); diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferManager.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferManager.cs index c104025c9fc..beb093b0169 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferManager.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferManager.cs @@ -4,6 +4,7 @@ using System; using System.Collections.Concurrent; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Options; @@ -14,18 +15,21 @@ internal sealed class GlobalLogBufferManager : GlobalLogBuffer internal readonly ConcurrentDictionary Buffers = []; private readonly IOptionsMonitor _options; private readonly TimeProvider _timeProvider; + private readonly IExternalScopeProvider _scopeProvider; - public GlobalLogBufferManager(IOptionsMonitor options) - : this(options, TimeProvider.System) + public GlobalLogBufferManager(IOptionsMonitor options, IExternalScopeProvider scopeProvider) + : this(options, TimeProvider.System, scopeProvider) { } internal GlobalLogBufferManager( IOptionsMonitor options, - TimeProvider timeProvider) + TimeProvider timeProvider, + IExternalScopeProvider scopeProvider) { _options = options; _timeProvider = timeProvider; + _scopeProvider = scopeProvider; } public override void Flush() @@ -44,14 +48,16 @@ public override bool TryEnqueue(IBufferedLogger bufferedLogger, in LogEn state.bufferedLogger, category, state._options, - state._timeProvider), - (bufferedLogger, _options, _timeProvider)); + state._timeProvider, + state._scopeProvider), + (bufferedLogger, _options, _timeProvider, _scopeProvider)); #else GlobalBuffer buffer = Buffers.GetOrAdd(category, category => new GlobalBuffer( bufferedLogger, category, _options, - _timeProvider)); + _timeProvider, + _scopeProvider)); #endif return buffer.TryEnqueue(logEntry); } diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingConfigureOptions.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingConfigureOptions.cs index 0d7c048497a..fa93bdef893 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingConfigureOptions.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingConfigureOptions.cs @@ -39,6 +39,7 @@ public void Configure(GlobalLogBufferingOptions options) options.MaxLogRecordSizeInBytes = parsedOptions.MaxLogRecordSizeInBytes; options.MaxBufferSizeInBytes = parsedOptions.MaxBufferSizeInBytes; options.AutoFlushDuration = parsedOptions.AutoFlushDuration; + options.IncludeScopes = parsedOptions.IncludeScopes; foreach (LogBufferingFilterRule rule in parsedOptions.Rules) { diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptions.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptions.cs index 24c05b425e4..222ca5ed9ca 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptions.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptions.cs @@ -5,7 +5,9 @@ using System; using System.Collections.Generic; using System.ComponentModel.DataAnnotations; +using System.Diagnostics.CodeAnalysis; using Microsoft.Shared.Data.Validation; +using Microsoft.Shared.DiagnosticIds; namespace Microsoft.Extensions.Diagnostics.Buffering; @@ -57,6 +59,16 @@ public class GlobalLogBufferingOptions [Range(MinimumBufferSizeInBytes, MaximumBufferSizeInBytes)] public int MaxBufferSizeInBytes { get; set; } = DefaultMaxBufferSizeInBytes; + /// + /// Gets or sets a value indicating whether logging scopes are added to the attributes of log records when they're buffered. + /// + /// + /// Only scopes that implement IEnumerable<KeyValuePair<string, object?>> are added, without their "{OriginalFormat}" pairs. + /// Scope values are converted to strings and count toward and . + /// + [Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] + public bool IncludeScopes { get; set; } + /// /// Gets or sets the collection of used for filtering log messages for the purpose of further buffering. /// diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.json b/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.json index 3ba17a4ba38..3614de33de4 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.json +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.json @@ -123,6 +123,10 @@ "Member": "System.TimeSpan Microsoft.Extensions.Diagnostics.Buffering.GlobalLogBufferingOptions.AutoFlushDuration { get; set; }", "Stage": "Stable" }, + { + "Member": "bool Microsoft.Extensions.Diagnostics.Buffering.GlobalLogBufferingOptions.IncludeScopes { get; set; }", + "Stage": "Experimental" + }, { "Member": "int Microsoft.Extensions.Diagnostics.Buffering.GlobalLogBufferingOptions.MaxBufferSizeInBytes { get; set; }", "Stage": "Stable" diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/README.md b/src/Libraries/Microsoft.Extensions.Telemetry/README.md index 1ce4788c610..e953f1f33e5 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/README.md +++ b/src/Libraries/Microsoft.Extensions.Telemetry/README.md @@ -113,11 +113,13 @@ public class MyService The Global Log Buffer supports the `IOptionsMonitor` pattern, allowing for dynamic configuration updates. This means you can change the buffering rules at runtime without needing to restart your application. +To preserve logging scopes in buffered log records, set the experimental `IncludeScopes` option, which adds the scopes' name/value pairs to the records' attributes. + #### Limitations 1. This library does not preserve the order of log records. However, original timestamps are preserved. 1. The library does not support custom configuration per each logger provider. Same configuration is applied to all logger providers. -1. Log scopes are not supported. This means that if you use `ILogger.BeginScope()` method, the buffered log records will not be associated with the scope. +1. Log scopes are only preserved if the `IncludeScopes` option is enabled, and then only as attributes of buffered log records. 1. When buffering and then flushing buffers, not all information of the original log record is preserved. This is due to serializing/deserializing limitation, but can be revisited in future. Namely, this library uses `Microsoft.Extensions.Logging.Abstractions.BufferedLogRecord` class when converting buffered log records to actual log records, but omits following properties: diff --git a/src/Shared/LogBuffering/SerializedLogRecordFactory.cs b/src/Shared/LogBuffering/SerializedLogRecordFactory.cs index 288c6532a46..1bcf476fae3 100644 --- a/src/Shared/LogBuffering/SerializedLogRecordFactory.cs +++ b/src/Shared/LogBuffering/SerializedLogRecordFactory.cs @@ -12,6 +12,8 @@ namespace Microsoft.Extensions.Diagnostics.Buffering; internal static class SerializedLogRecordFactory { + private const string OriginalFormat = "{OriginalFormat}"; + private static readonly ObjectPool>> _attributesPool = PoolFactory.CreateListPool>(); @@ -23,7 +25,8 @@ public static SerializedLogRecord Create( DateTimeOffset timestamp, IReadOnlyList> attributes, Exception? exception, - string formattedMessage) + string formattedMessage, + IExternalScopeProvider? scopeProvider) { int sizeInBytes = _serializedLogRecordSize; List> serializedAttributes = _attributesPool.Get(); @@ -40,6 +43,11 @@ public static SerializedLogRecord Create( serializedAttributes.Add(new KeyValuePair(key, value)); } + if (scopeProvider is not null) + { + sizeInBytes += AddScopes(serializedAttributes, scopeProvider); + } + string exceptionMessage = string.Empty; if (exception is not null) { @@ -64,6 +72,57 @@ public static void Return(SerializedLogRecord bufferedRecord) _attributesPool.Return(bufferedRecord.Attributes); } + /// + /// Adds the name/value pairs of the current scopes to the attributes of a log record. + /// + /// The approximate size in bytes of the added values. + private static int AddScopes(List> serializedAttributes, IExternalScopeProvider scopeProvider) + { + int count = serializedAttributes.Count; + scopeProvider.ForEachScope(static (scope, attributes) => + { + if (scope is IReadOnlyList> list) + { + for (int i = 0; i < list.Count; i++) + { + AddScopeItem(attributes, list[i]); + } + } + else if (scope is IEnumerable> items) + { + foreach (KeyValuePair item in items) + { + AddScopeItem(attributes, item); + } + } + }, serializedAttributes); + + int sizeInBytes = 0; + for (int i = count; i < serializedAttributes.Count; i++) + { + sizeInBytes += CalculateStringSize((string)serializedAttributes[i].Value!); + } + + // "{OriginalFormat}" needs to stay the last attribute. + if (count > 0 && serializedAttributes[count - 1].Key == OriginalFormat) + { + KeyValuePair originalFormat = serializedAttributes[count - 1]; + serializedAttributes.RemoveAt(count - 1); + serializedAttributes.Add(originalFormat); + } + + return sizeInBytes; + } + + private static void AddScopeItem(List> attributes, KeyValuePair item) + { + // Skips the scope's {OriginalFormat} in favor of the log record's own {OriginalFormat}. + if (item.Key != OriginalFormat) + { + attributes.Add(new KeyValuePair(item.Key, item.Value?.ToString() ?? string.Empty)); + } + } + private static int CalculateStringSize(string str) { if (string.IsNullOrEmpty(str)) diff --git a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerIncomingRequestLoggingBuilderExtensionsTests.cs b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerIncomingRequestLoggingBuilderExtensionsTests.cs index 5bad831ab68..f62a69ec873 100644 --- a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerIncomingRequestLoggingBuilderExtensionsTests.cs +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerIncomingRequestLoggingBuilderExtensionsTests.cs @@ -91,6 +91,16 @@ public void WhenConfigurationActionProvided_RegistersInDI() Assert.Equivalent(expectedData, options.CurrentValue.Rules); } + [Fact] + public void WhenConfigurationActionProvided_AppliesIncludeScopesToGlobalBuffer() + { + var serviceCollection = new ServiceCollection(); + serviceCollection.AddLogging(b => b.AddPerIncomingRequestBuffer(options => options.IncludeScopes = true)); + using ServiceProvider serviceProvider = serviceCollection.BuildServiceProvider(); + + Assert.True(serviceProvider.GetRequiredService>().CurrentValue.IncludeScopes); + } + [Fact] public async Task WhenConfigUpdated_PicksUpConfigChanges() { diff --git a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingIncludeScopesTests.cs b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingIncludeScopesTests.cs new file mode 100644 index 00000000000..f951a0c79f4 --- /dev/null +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingIncludeScopesTests.cs @@ -0,0 +1,61 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +#if NET9_0_OR_GREATER + +using System.Net.Http; +using System.Threading.Tasks; +using Microsoft.AspNetCore.Builder; +using Microsoft.AspNetCore.Hosting; +using Microsoft.AspNetCore.TestHost; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Hosting.Testing; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Testing; +using Xunit; + +namespace Microsoft.AspNetCore.Diagnostics.Buffering.Test; + +public class PerRequestLogBufferingIncludeScopesTests +{ + private const string RequestPath = "/scoped"; + + [Theory] + [InlineData(true)] + [InlineData(false)] + public async Task IncludeScopes_ControlsWhetherScopesAreAddedToBufferedLogRecords(bool includeScopes) + { + using IHost host = await FakeHost.CreateBuilder() + .ConfigureWebHost(builder => builder + .UseTestServer() + .ConfigureLogging(logging => logging + .AddPerIncomingRequestBuffer(options => + { + options.IncludeScopes = includeScopes; + options.Rules.Add(new LogBufferingFilterRule(categoryName: "test", logLevel: LogLevel.Information)); + })) + .Configure(app => app.Run(static context => + { + ILogger logger = context.RequestServices.GetRequiredService().CreateLogger("test"); + using (logger.BeginScope("Order {OrderId}", 42)) + { + logger.LogInformation("buffered"); + } + + context.RequestServices.GetRequiredService().Flush(); + return Task.CompletedTask; + }))) + .StartAsync(); + + using HttpClient client = host.GetTestClient(); + using HttpResponseMessage response = await client.GetAsync(RequestPath); + + FakeLogRecord record = Assert.Single(host.GetFakeLogCollector().GetSnapshot(), r => r.Message == "buffered"); + Assert.Equal(includeScopes ? "42" : null, record.GetStructuredStateValue("OrderId")); + + // The request scope is begun by ASP.NET Core with a different logger than the one which logged the record. + Assert.Equal(includeScopes ? RequestPath : null, record.GetStructuredStateValue("RequestPath")); + } +} +#endif diff --git a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingOptionsConfigureOptionsTests.cs b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingOptionsConfigureOptionsTests.cs index 15431fa3bdb..ad1178ec483 100644 --- a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingOptionsConfigureOptionsTests.cs +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingOptionsConfigureOptionsTests.cs @@ -72,6 +72,7 @@ public void Configure_WithValidConfiguration_UpdatesOptions() { ["PerIncomingRequestLogBuffering:MaxLogRecordSizeInBytes"] = "1024", ["PerIncomingRequestLogBuffering:MaxPerRequestBufferSizeInBytes"] = "4096", + ["PerIncomingRequestLogBuffering:IncludeScopes"] = "true", ["PerIncomingRequestLogBuffering:Rules:0:CategoryName"] = "TestCategory", ["PerIncomingRequestLogBuffering:Rules:0:LogLevel"] = "Information" }; @@ -89,6 +90,7 @@ public void Configure_WithValidConfiguration_UpdatesOptions() // Assert Assert.Equal(1024, options.MaxLogRecordSizeInBytes); Assert.Equal(4096, options.MaxPerRequestBufferSizeInBytes); + Assert.True(options.IncludeScopes); Assert.Single(options.Rules); Assert.Equal("TestCategory", options.Rules[0].CategoryName); Assert.Equal(LogLevel.Information, options.Rules[0].LogLevel); diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferIncludeScopesTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferIncludeScopesTests.cs new file mode 100644 index 00000000000..0169843c71a --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferIncludeScopesTests.cs @@ -0,0 +1,173 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +#if NET9_0_OR_GREATER + +using System; +using System.Collections; +using System.Collections.Generic; +using System.Diagnostics; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Test; +using Microsoft.Extensions.Logging.Testing; +using Xunit; + +namespace Microsoft.Extensions.Diagnostics.Buffering.Test; + +public class GlobalBufferIncludeScopesTests +{ + [Fact] + public void AddsScopesToAttributesOfBufferedLogRecords() + { + using var provider = new FakeLoggerProvider(); + using ILoggerFactory factory = CreateLoggerFactory(provider, includeScopes: true); + ILogger logger = factory.CreateLogger("my category"); + + using (logger.BeginScope("plain scope")) + using (logger.BeginScope(new Dictionary { ["Tenant"] = "contoso" })) + using (logger.BeginScope("Order {OrderId}", 42)) + { + logger.LogWarning("buffered {Number}", 1); + } + + GetBuffer(factory).Flush(); + + FakeLogRecord record = Assert.Single(provider.Collector.GetSnapshot()); + Assert.Equal( + new KeyValuePair[] { new("Number", "1"), new("OrderId", "42"), new("{OriginalFormat}", "buffered {Number}") }, + record.StructuredState); + } + + [Fact] + public void WhenLogRecordHasNoOriginalFormat_AddsScopesAfterItsAttributes() + { + using var provider = new FakeLoggerProvider(); + using ILoggerFactory factory = CreateLoggerFactory(provider, includeScopes: true); + ILogger logger = factory.CreateLogger("my category"); + + using (logger.BeginScope("Order {OrderId}", 42)) + { + logger.Log(LogLevel.Warning, default, new KeyValuePair[] { new("Number", 1) }, null, static (_, _) => "buffered"); + } + + GetBuffer(factory).Flush(); + + FakeLogRecord record = Assert.Single(provider.Collector.GetSnapshot()); + Assert.Equal(new KeyValuePair[] { new("Number", "1"), new("OrderId", "42") }, record.StructuredState); + } + + [Fact] + public void WhenIncludeScopesIsDisabled_DoesNotAddScopes() + { + using var provider = new FakeLoggerProvider(); + using ILoggerFactory factory = CreateLoggerFactory(provider, includeScopes: false); + ILogger logger = factory.CreateLogger("my category"); + + using (logger.BeginScope("Order {OrderId}", 42)) + { + logger.LogWarning("buffered"); + } + + GetBuffer(factory).Flush(); + + FakeLogRecord record = Assert.Single(provider.Collector.GetSnapshot()); + Assert.Equal(new KeyValuePair[] { new("{OriginalFormat}", "buffered") }, record.StructuredState); + } + + [Fact] + public void AddsScopeValuesAsTheyAreWhenLogRecordIsBuffered() + { + using var provider = new FakeLoggerProvider(); + using ILoggerFactory factory = CreateLoggerFactory(provider, includeScopes: true); + ILogger logger = factory.CreateLogger("my category"); + + var scope = new MutableKeyValueScope { Value = "original" }; + using (logger.BeginScope(scope)) + { + logger.LogWarning("buffered"); + } + + scope.Value = "changed"; + GetBuffer(factory).Flush(); + + FakeLogRecord record = Assert.Single(provider.Collector.GetSnapshot()); + Assert.Equal("original", record.GetStructuredStateValue("Key")); + } + + [Fact] + public void AddsActivityScope() + { + using var provider = new FakeLoggerProvider(); + using ILoggerFactory factory = CreateLoggerFactory( + provider, + includeScopes: true, + builder => builder.Configure(options => options.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId)); + ILogger logger = factory.CreateLogger("my category"); + + using var activity = new Activity("logging"); + activity.Start(); + logger.LogWarning("buffered"); + + GetBuffer(factory).Flush(); + + FakeLogRecord record = Assert.Single(provider.Collector.GetSnapshot()); + Assert.Equal(activity.TraceId.ToHexString(), record.GetStructuredStateValue("TraceId")); + Assert.Equal(activity.SpanId.ToHexString(), record.GetStructuredStateValue("SpanId")); + } + + [Fact] + public void ScopeValuesCountTowardMaxLogRecordSize() + { + using var provider = new FakeLoggerProvider(); + using ILoggerFactory factory = Utils.CreateLoggerFactory(builder => + { + builder.AddProvider(provider); + builder.AddGlobalBuffer(options => + { + options.IncludeScopes = true; + options.MaxLogRecordSizeInBytes = 1024; + options.Rules.Add(new LogBufferingFilterRule(logLevel: LogLevel.Warning)); + }); + }); + ILogger logger = factory.CreateLogger("my category"); + + logger.LogWarning("buffered"); + using (logger.BeginScope("{Value}", new string('a', 1024))) + { + logger.LogWarning("too big to be buffered"); + } + + // The log record which exceeds the size limit together with its scopes is emitted right away. + FakeLogRecord record = Assert.Single(provider.Collector.GetSnapshot()); + Assert.Equal("too big to be buffered", record.Message); + } + + private static ILoggerFactory CreateLoggerFactory(ILoggerProvider provider, bool includeScopes, Action? configure = null) => + Utils.CreateLoggerFactory(builder => + { + builder.AddProvider(provider); + builder.AddGlobalBuffer(options => + { + options.IncludeScopes = includeScopes; + options.Rules.Add(new LogBufferingFilterRule(logLevel: LogLevel.Warning)); + }); + + configure?.Invoke(builder); + }); + + private static GlobalLogBuffer GetBuffer(ILoggerFactory factory) => + ((Utils.DisposingLoggerFactory)factory).ServiceProvider.GetRequiredService(); + + private sealed class MutableKeyValueScope : IEnumerable> + { + public string? Value { get; set; } + + public IEnumerator> GetEnumerator() + { + yield return new KeyValuePair("Key", Value); + } + + IEnumerator IEnumerable.GetEnumerator() => GetEnumerator(); + } +} +#endif diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalLogBufferingConfigureOptionsTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalLogBufferingConfigureOptionsTests.cs index 8f99ef12183..ef203c70ff2 100644 --- a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalLogBufferingConfigureOptionsTests.cs +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalLogBufferingConfigureOptionsTests.cs @@ -71,6 +71,7 @@ public void Configure_WithValidConfiguration_UpdatesOptions() { ["GlobalLogBuffering:MaxLogRecordSizeInBytes"] = "1024", ["GlobalLogBuffering:MaxBufferSizeInBytes"] = "4096", + ["GlobalLogBuffering:IncludeScopes"] = "true", ["GlobalLogBuffering:Rules:0:CategoryName"] = "TestCategory", ["GlobalLogBuffering:Rules:0:LogLevel"] = "Information" }; @@ -88,6 +89,7 @@ public void Configure_WithValidConfiguration_UpdatesOptions() // Assert Assert.Equal(1024, options.MaxLogRecordSizeInBytes); Assert.Equal(4096, options.MaxBufferSizeInBytes); + Assert.True(options.IncludeScopes); Assert.Single(options.Rules); Assert.Equal("TestCategory", options.Rules[0].CategoryName); Assert.Equal(LogLevel.Information, options.Rules[0].LogLevel);