diff --git a/eng/MSBuild/ProjectStaging.props b/eng/MSBuild/ProjectStaging.props index 95fed0f1e31..9e3abad4a7c 100644 --- a/eng/MSBuild/ProjectStaging.props +++ b/eng/MSBuild/ProjectStaging.props @@ -11,12 +11,6 @@ --> <_IsStable Condition="('$(Stage)' != 'dev' and '$(Stage)' != 'preview') Or '$(MSBuildProjectName)' == 'Microsoft.AspNetCore.Testing'">true - - release - $(NoWarn);LA0003 false + + + + true @@ -74,7 +83,7 @@ 10.0.0-preview.3.25151.1 10.0.0-preview.3.25151.1 - 9.0.3 + 9.0.4 10.0.0-beta.25126.4 diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBuffer.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBuffer.cs new file mode 100644 index 00000000000..1b5da2e7f3d --- /dev/null +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBuffer.cs @@ -0,0 +1,164 @@ +// 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.Concurrent; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.ObjectPool; +using Microsoft.Extensions.Options; +using Microsoft.Shared.Diagnostics; +using Microsoft.Shared.Pools; + +namespace Microsoft.AspNetCore.Diagnostics.Buffering; + +internal sealed class IncomingRequestLogBuffer : IDisposable +{ + private const int MaxBatchSize = 256; + private static readonly ObjectPool> _recordsToEmitListPool = + PoolFactory.CreateListPoolWithCapacity(MaxBatchSize); + + private readonly IBufferedLogger _bufferedLogger; + private readonly LogBufferingFilterRuleSelector _ruleSelector; + private readonly IOptionsMonitor _options; + private readonly TimeProvider _timeProvider = TimeProvider.System; + private readonly LogBufferingFilterRule[] _filterRules; + private readonly Lock _bufferSwapLock = new(); + private volatile bool _disposed; + private ConcurrentQueue _activeBuffer = new(); + private ConcurrentQueue _standbyBuffer = new(); + private int _activeBufferSize; + private DateTimeOffset _lastFlushTimestamp; + + public IncomingRequestLogBuffer( + IBufferedLogger bufferedLogger, + string category, + LogBufferingFilterRuleSelector ruleSelector, + IOptionsMonitor options) + { + _bufferedLogger = bufferedLogger; + _ruleSelector = ruleSelector; + _options = options; + _filterRules = LogBufferingFilterRuleSelector.SelectByCategory(_options.CurrentValue.Rules.ToArray(), category); + } + + public bool TryEnqueue(LogEntry logEntry) + { + if (_timeProvider.GetUtcNow() < _lastFlushTimestamp + _options.CurrentValue.AutoFlushDuration) + { + return false; + } + + IReadOnlyList>? attributes = logEntry.State as IReadOnlyList>; + if (attributes is null) + { + // we expect state to be either ModernTagJoiner or LegacyTagJoiner + // which both implement IReadOnlyList> + // and if not, we throw an exception + Throw.InvalidOperationException( + $"Unsupported type of log state detected: {typeof(TState)}, expected IReadOnlyList>"); + } + + if (_ruleSelector.Select(_filterRules, logEntry.LogLevel, logEntry.EventId, attributes) is null) + { + // buffering is not enabled for this log entry, + // return false to indicate that the log entry should be logged normally. + return false; + } + + SerializedLogRecord serializedLogRecord = SerializedLogRecordFactory.Create( + logEntry.LogLevel, + logEntry.EventId, + _timeProvider.GetUtcNow(), + attributes, + logEntry.Exception, + logEntry.Formatter(logEntry.State, logEntry.Exception)); + + if (serializedLogRecord.SizeInBytes > _options.CurrentValue.MaxLogRecordSizeInBytes) + { + SerializedLogRecordFactory.Return(serializedLogRecord); + return false; + } + + lock (_bufferSwapLock) + { + _activeBuffer.Enqueue(serializedLogRecord); + _ = Interlocked.Add(ref _activeBufferSize, serializedLogRecord.SizeInBytes); + + } + + TrimExcessRecords(); + + return true; + } + + public void Flush() + { + _lastFlushTimestamp = _timeProvider.GetUtcNow(); + + ConcurrentQueue tempBuffer; + int numItemsToEmit; + lock (_bufferSwapLock) + { + tempBuffer = _activeBuffer; + _activeBuffer = _standbyBuffer; + _standbyBuffer = tempBuffer; + + numItemsToEmit = tempBuffer.Count; + + _ = Interlocked.Exchange(ref _activeBufferSize, 0); + } + + for (int offset = 0; offset < numItemsToEmit && !tempBuffer.IsEmpty; offset += MaxBatchSize) + { + int currentBatchSize = Math.Min(MaxBatchSize, numItemsToEmit - offset); + List recordsToEmit = _recordsToEmitListPool.Get(); + try + { + for (int i = 0; i < currentBatchSize && tempBuffer.TryDequeue(out SerializedLogRecord bufferedRecord); i++) + { + recordsToEmit.Add(new DeserializedLogRecord( + bufferedRecord.Timestamp, + bufferedRecord.LogLevel, + bufferedRecord.EventId, + bufferedRecord.Exception, + bufferedRecord.FormattedMessage, + bufferedRecord.Attributes)); + } + + _bufferedLogger.LogRecords(recordsToEmit); + } + finally + { + _recordsToEmitListPool.Return(recordsToEmit); + } + } + } + + public void Dispose() + { + if (_disposed) + { + return; + } + + _disposed = true; + + _ruleSelector.InvalidateCache(); + } + + private void TrimExcessRecords() + { + while (_activeBufferSize > _options.CurrentValue.MaxPerRequestBufferSizeInBytes && + _activeBuffer.TryDequeue(out SerializedLogRecord item)) + { + _ = Interlocked.Add(ref _activeBufferSize, -item.SizeInBytes); + SerializedLogRecordFactory.Return(item); + } + } +} +#endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBufferHolder.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBufferHolder.cs new file mode 100644 index 00000000000..e46869a083b --- /dev/null +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBufferHolder.cs @@ -0,0 +1,40 @@ +// 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.Concurrent; + +namespace Microsoft.AspNetCore.Diagnostics.Buffering; + +internal sealed class IncomingRequestLogBufferHolder : IDisposable +{ + private readonly ConcurrentDictionary _buffers = new(); + private bool _disposed; + + public IncomingRequestLogBuffer GetOrAdd(string category, Func valueFactory) => + _buffers.GetOrAdd(category, valueFactory); + + public void Flush() + { + foreach (IncomingRequestLogBuffer buffer in _buffers.Values) + { + buffer.Flush(); + } + } + + public void Dispose() + { + if (_disposed) + { + return; + } + + _disposed = true; + + foreach (IncomingRequestLogBuffer buffer in _buffers.Values) + { + buffer.Dispose(); + } + } +} +#endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerIncomingRequestLoggingBuilderExtensions.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerIncomingRequestLoggingBuilderExtensions.cs new file mode 100644 index 00000000000..8d3f7411367 --- /dev/null +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerIncomingRequestLoggingBuilderExtensions.cs @@ -0,0 +1,124 @@ +// 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.Diagnostics.CodeAnalysis; +using Microsoft.AspNetCore.Diagnostics.Buffering; +using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; +using Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Options; +using Microsoft.Shared.DiagnosticIds; +using Microsoft.Shared.Diagnostics; + +namespace Microsoft.Extensions.Logging; + +/// +/// Lets you register per incoming request log buffering in a dependency injection container. +/// +[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] +public static class PerIncomingRequestLoggingBuilderExtensions +{ + /// + /// Adds per incoming request log buffering to the logging infrastructure. + /// + /// The . + /// The to add. + /// The value of . + /// or is . + /// + /// Matched logs will be buffered in a buffer specific to each incoming request + /// and can optionally be flushed and emitted during the request lifetime. + /// + public static ILoggingBuilder AddPerIncomingRequestBuffer(this ILoggingBuilder builder, IConfiguration configuration) + { + _ = Throw.IfNull(builder); + _ = Throw.IfNull(configuration); + + _ = builder.Services + .AddSingleton>(new PerRequestLogBufferingConfigureOptions(configuration)) + .AddOptionsWithValidateOnStart() + .Services.AddOptionsWithValidateOnStart(); + + return builder + .AddPerRequestBufferManager() + .AddGlobalBuffer(configuration); + } + + /// + /// Adds per incoming request log buffering to the logging infrastructure. + /// + /// The . + /// The buffering options configuration delegate. + /// The value of . + /// or is . + /// + /// Matched logs will be buffered in a buffer specific to each incoming request + /// and can optionally be flushed and emitted during the request lifetime. + /// + public static ILoggingBuilder AddPerIncomingRequestBuffer(this ILoggingBuilder builder, Action configure) + { + _ = Throw.IfNull(builder); + _ = Throw.IfNull(configure); + + _ = builder.Services + .AddOptionsWithValidateOnStart() + .Services.AddOptionsWithValidateOnStart() + .Configure(configure); + + PerRequestLogBufferingOptions options = new PerRequestLogBufferingOptions(); + configure(options); + + return builder + .AddPerRequestBufferManager() + .AddGlobalBuffer(opts => opts.Rules = options.Rules); + } + + /// + /// Adds per incoming request log buffering to the logging infrastructure. + /// + /// The . + /// The level (and below) of logs to buffer. + /// The value of . + /// is . + /// + /// Matched logs will be buffered in a buffer specific to each incoming request + /// and can optionally be flushed and emitted during the request lifetime. + /// + public static ILoggingBuilder AddPerIncomingRequestBuffer(this ILoggingBuilder builder, LogLevel? logLevel = null) + { + _ = Throw.IfNull(builder); + + _ = builder.Services + .AddOptionsWithValidateOnStart() + .Services.AddOptionsWithValidateOnStart() + .Configure(options => + { + options.Rules.Add(new LogBufferingFilterRule(logLevel: logLevel)); + }); + + return builder + .AddPerRequestBufferManager() + .AddGlobalBuffer(logLevel); + } + + private static ILoggingBuilder AddPerRequestBufferManager(this ILoggingBuilder builder) + { + builder.Services.TryAddScoped(); + builder.Services.TryAddSingleton(); + builder.Services.TryAddSingleton(sp => + { + var globalBufferManager = sp.GetRequiredService(); + return ActivatorUtilities.CreateInstance(sp, globalBufferManager); + }); + builder.Services.TryAddSingleton(sp => sp.GetRequiredService()); + builder.Services.TryAddSingleton(sp => sp.GetRequiredService()); + + return builder; + } +} + +#endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferManager.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferManager.cs new file mode 100644 index 00000000000..de51e26eb58 --- /dev/null +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferManager.cs @@ -0,0 +1,60 @@ +// 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 Microsoft.AspNetCore.Http; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Options; + +namespace Microsoft.AspNetCore.Diagnostics.Buffering; + +internal sealed class PerRequestLogBufferManager : PerRequestLogBuffer +{ + private readonly GlobalLogBuffer _globalBuffer; + private readonly IHttpContextAccessor _httpContextAccessor; + private readonly LogBufferingFilterRuleSelector _ruleSelector; + private readonly IOptionsMonitor _options; + + public PerRequestLogBufferManager( + GlobalLogBuffer globalBuffer, + IHttpContextAccessor httpContextAccessor, + LogBufferingFilterRuleSelector ruleSelector, + IOptionsMonitor options) + { + _globalBuffer = globalBuffer; + _httpContextAccessor = httpContextAccessor; + _ruleSelector = ruleSelector; + _options = options; + } + + public override void Flush() + { + _httpContextAccessor.HttpContext?.RequestServices.GetService()?.Flush(); + _globalBuffer.Flush(); + } + + public override bool TryEnqueue(IBufferedLogger bufferedLogger, in LogEntry logEntry) + { + HttpContext? httpContext = _httpContextAccessor.HttpContext; + if (httpContext is null) + { + return _globalBuffer.TryEnqueue(bufferedLogger, logEntry); + } + + string category = logEntry.Category; + IncomingRequestLogBufferHolder? bufferHolder = + httpContext.RequestServices.GetService(); + IncomingRequestLogBuffer? buffer = bufferHolder?.GetOrAdd(category, _ => + new IncomingRequestLogBuffer(bufferedLogger, category, _ruleSelector, _options)); + + if (buffer is null) + { + return _globalBuffer.TryEnqueue(bufferedLogger, logEntry); + } + + return buffer.TryEnqueue(logEntry); + } +} +#endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingConfigureOptions.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingConfigureOptions.cs new file mode 100644 index 00000000000..54e1e2dc674 --- /dev/null +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingConfigureOptions.cs @@ -0,0 +1,49 @@ +// 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 Microsoft.Extensions.Configuration; +using Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Options; + +namespace Microsoft.AspNetCore.Diagnostics.Buffering; + +internal sealed class PerRequestLogBufferingConfigureOptions : IConfigureOptions +{ + private const string ConfigSectionName = "PerIncomingRequestLogBuffering"; + private readonly IConfiguration _configuration; + + public PerRequestLogBufferingConfigureOptions(IConfiguration configuration) + { + _configuration = configuration; + } + + public void Configure(PerRequestLogBufferingOptions options) + { + if (_configuration is null) + { + return; + } + + IConfigurationSection section = _configuration.GetSection(ConfigSectionName); + if (!section.Exists()) + { + return; + } + + var parsedOptions = section.Get(); + if (parsedOptions is null) + { + return; + } + + options.MaxLogRecordSizeInBytes = parsedOptions.MaxLogRecordSizeInBytes; + options.MaxPerRequestBufferSizeInBytes = parsedOptions.MaxPerRequestBufferSizeInBytes; + options.AutoFlushDuration = parsedOptions.AutoFlushDuration; + + foreach (LogBufferingFilterRule rule in parsedOptions.Rules) + { + options.Rules.Add(rule); + } + } +} +#endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptions.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptions.cs new file mode 100644 index 00000000000..0b281f06edb --- /dev/null +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptions.cs @@ -0,0 +1,79 @@ +// 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.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; + +/// +/// The options for log buffering per each incoming request. +/// +[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] +public class PerRequestLogBufferingOptions +{ + private const int DefaultPerRequestBufferSizeInBytes = 500 * 1024 * 1024; // 500 MB. + private const int DefaultMaxLogRecordSizeInBytes = 50 * 1024; // 50 KB. + + private const int MinimumAutoFlushDuration = 0; + private const int MaximumAutoFlushDuration = 1000 * 60 * 60 * 24; // 1 day. + + private const long MinimumPerRequestBufferSizeInBytes = 1; + private const long MaximumPerRequestBufferSizeInBytes = 10L * 1024 * 1024 * 1024; // 10 GB. + + private const long MinimumLogRecordSizeInBytes = 1; + private const long MaximumLogRecordSizeInBytes = 10 * 1024 * 1024; // 10 MB. + + private static readonly TimeSpan _defaultAutoFlushDuration = TimeSpan.FromSeconds(30); + + /// + /// Gets or sets the time to do automatic flushing after manual flushing was triggered. + /// + /// + /// Use this to temporarily suspend buffering after a flush, e.g. in case of an incident you may want all logs to be emitted immediately, + /// so the buffering will be suspended for the time. + /// + [TimeSpan(MinimumAutoFlushDuration, MaximumAutoFlushDuration)] + public TimeSpan AutoFlushDuration { get; set; } = _defaultAutoFlushDuration; + + /// + /// Gets or sets the maximum size of each individual log record in bytes. + /// + /// + /// If the size of a log record exceeds this limit, it won't be buffered. + /// + [Range(MinimumLogRecordSizeInBytes, MaximumLogRecordSizeInBytes)] + public int MaxLogRecordSizeInBytes { get; set; } = DefaultMaxLogRecordSizeInBytes; + + /// + /// Gets or sets the maximum size of each per request buffer in bytes. + /// + /// + /// If adding a new log entry would cause the buffer size to exceed this limit, + /// the oldest buffered log records will be dropped to make room. + /// + [Range(MinimumPerRequestBufferSizeInBytes, MaximumPerRequestBufferSizeInBytes)] + public int MaxPerRequestBufferSizeInBytes { get; set; } = DefaultPerRequestBufferSizeInBytes; + +#pragma warning disable CA2227 // Collection properties should be read only - setter is necessary for options pattern + /// + /// Gets or sets the collection of used for filtering log messages for the purpose of further buffering. + /// + /// + /// If a log entry matches a rule, it will be buffered for the lifetime and scope of the respective incoming request. + /// Consequently, it will later be emitted when the buffer is flushed. + /// When the request finishes, and flush has not happened, buffered log entries of that specific request will be dropped. + /// If a log entry does not match any rule, it will be emitted normally. + /// If the buffer size limit is reached, the oldest buffered log entries will be dropped (not emitted!) to make room for new ones. + /// If a log entry size is greater than , it will not be buffered and will be emitted normally. + /// + public IList Rules { get; set; } = []; +#pragma warning restore CA2227 +} +#endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptionsCustomValidator.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptionsCustomValidator.cs new file mode 100644 index 00000000000..9db4c1ec183 --- /dev/null +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptionsCustomValidator.cs @@ -0,0 +1,35 @@ +// 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 Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Options; + +namespace Microsoft.AspNetCore.Diagnostics.Buffering; + +internal sealed class PerRequestLogBufferingOptionsCustomValidator : IValidateOptions +{ + private const char WildcardChar = '*'; + + public ValidateOptionsResult Validate(string? name, PerRequestLogBufferingOptions options) + { + ValidateOptionsResultBuilder resultBuilder = new(); + foreach (LogBufferingFilterRule rule in options.Rules) + { + if (rule.CategoryName is null) + { + continue; + } + + int wildcardIndex = rule.CategoryName.IndexOf(WildcardChar, StringComparison.Ordinal); + if (wildcardIndex >= 0 && rule.CategoryName.IndexOf(WildcardChar, wildcardIndex + 1) >= 0) + { + resultBuilder.AddError("Only one wildcard character is allowed in category name.", nameof(options.Rules)); + } + } + + return resultBuilder.Build(); + } +} +#endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptionsValidator.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptionsValidator.cs new file mode 100644 index 00000000000..6077472e928 --- /dev/null +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/PerRequestLogBufferingOptionsValidator.cs @@ -0,0 +1,13 @@ +// 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 Microsoft.Extensions.Options; + +namespace Microsoft.AspNetCore.Diagnostics.Buffering; + +[OptionsValidator] +internal sealed partial class PerRequestLogBufferingOptionsValidator : IValidateOptions +{ +} +#endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Microsoft.AspNetCore.Diagnostics.Middleware.csproj b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Microsoft.AspNetCore.Diagnostics.Middleware.csproj index 4cc1cbfeff3..e9c7b9b521f 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Microsoft.AspNetCore.Diagnostics.Middleware.csproj +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Microsoft.AspNetCore.Diagnostics.Middleware.csproj @@ -10,19 +10,19 @@ $(NetCoreTargetFrameworks) true true - false - false + true true false false true false - true + false + false normal - 100 + 98 85 diff --git a/src/Libraries/Microsoft.Extensions.AI.Evaluation.Reporting/TypeScript/components/App.tsx b/src/Libraries/Microsoft.Extensions.AI.Evaluation.Reporting/TypeScript/components/App.tsx index 7cb0b26558d..da256800221 100644 --- a/src/Libraries/Microsoft.Extensions.AI.Evaluation.Reporting/TypeScript/components/App.tsx +++ b/src/Libraries/Microsoft.Extensions.AI.Evaluation.Reporting/TypeScript/components/App.tsx @@ -55,7 +55,7 @@ function App() { const toggleSettings = () => setIsSettingsOpen(!isSettingsOpen); const closeSettings = () => setIsSettingsOpen(false); - const downloadDataset = () => { + const downloadDataset = () => { // create a stringified JSON of the dataset const dataStr = JSON.stringify(dataset, null, 2); diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogger.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogger.cs index 56973c9e78d..20b4fde8512 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogger.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogger.cs @@ -6,6 +6,11 @@ using System.Collections.Concurrent; using System.Collections.Generic; using System.Globalization; +#if NET9_0_OR_GREATER +using System.Diagnostics.CodeAnalysis; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Shared.DiagnosticIds; +#endif using Microsoft.Shared.Diagnostics; namespace Microsoft.Extensions.Logging.Testing; @@ -17,7 +22,11 @@ namespace Microsoft.Extensions.Logging.Testing; /// This type is intended for use in unit tests. It captures all the log state to memory and lets you inspect it /// to validate that your code is logging what it should. /// +#if NET9_0_OR_GREATER +public class FakeLogger : ILogger, IBufferedLogger +#else public class FakeLogger : ILogger +#endif { private readonly ConcurrentDictionary _disabledLevels = new(); // used as a set, the value is ignored @@ -105,6 +114,27 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except /// public string? Category { get; } +#if NET9_0_OR_GREATER + /// + [Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] + public void LogRecords(IEnumerable records) + { + _ = Throw.IfNull(records); + + var l = new List(); + + foreach (var rec in records) + { +#pragma warning disable CA2201 // Do not raise reserved exception types + var exception = rec.Exception is not null ? new Exception(rec.Exception) : null; +#pragma warning restore CA2201 // Do not raise reserved exception types + var record = new FakeLogRecord(rec.LogLevel, rec.EventId, ConsumeTState(rec.Attributes), exception, rec.FormattedMessage ?? string.Empty, + l.ToArray(), Category, !_disabledLevels.ContainsKey(rec.LogLevel), rec.Timestamp); + Collector.AddRecord(record); + } + } +#endif + internal IExternalScopeProvider ScopeProvider { get; set; } = new LoggerExternalScopeProvider(); private static object? ConsumeTState(object? state) diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Microsoft.Extensions.Diagnostics.Testing.csproj b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Microsoft.Extensions.Diagnostics.Testing.csproj index 01f3b954262..2ab592c4a4a 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Microsoft.Extensions.Diagnostics.Testing.csproj +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Microsoft.Extensions.Diagnostics.Testing.csproj @@ -1,4 +1,4 @@ - + Microsoft.Extensions.Diagnostics.Testing Hand-crafted fakes to make telemetry-related testing easier. diff --git a/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Buffering/GlobalLogBuffer.cs b/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Buffering/GlobalLogBuffer.cs new file mode 100644 index 00000000000..d5d8185421b --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Buffering/GlobalLogBuffer.cs @@ -0,0 +1,14 @@ +// 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 + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +/// +/// Buffers logs into global circular buffers and drops them after some time if not flushed. +/// +public abstract class GlobalLogBuffer : LogBuffer +{ +} + +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Buffering/LogBuffer.cs b/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Buffering/LogBuffer.cs new file mode 100644 index 00000000000..4853615c228 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Buffering/LogBuffer.cs @@ -0,0 +1,34 @@ +// 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.Diagnostics.CodeAnalysis; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Shared.DiagnosticIds; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +/// +/// Buffers logs into circular buffers and drops them after some time if not flushed. +/// +[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] +#pragma warning disable S1694 // An abstract class should have both abstract and concrete methods +public abstract class LogBuffer +#pragma warning restore S1694 // An abstract class should have both abstract and concrete methods +{ + /// + /// Flushes the buffer and emits all buffered logs. + /// + public abstract void Flush(); + + /// + /// Enqueues a log record in the underlying buffer, if available. + /// + /// A logger capable of logging buffered log records. + /// A log entry to be buffered. + /// Type of the log state in the instance. + /// if the log record was buffered; otherwise, . + public abstract bool TryEnqueue(IBufferedLogger bufferedLogger, in LogEntry logEntry); +} + +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Buffering/PerRequestLogBuffer.cs b/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Buffering/PerRequestLogBuffer.cs new file mode 100644 index 00000000000..cde1756ff84 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry.Abstractions/Buffering/PerRequestLogBuffer.cs @@ -0,0 +1,14 @@ +// 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 + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +/// +/// Buffers logs into per-request circular buffers and drops them after some time if not flushed or when the request ends. +/// +public abstract class PerRequestLogBuffer : LogBuffer +{ +} + +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferedLoggerProxy.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferedLoggerProxy.cs new file mode 100644 index 00000000000..1e33c05e81a --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferedLoggerProxy.cs @@ -0,0 +1,49 @@ +// 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.Generic; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +internal sealed class BufferedLoggerProxy : IBufferedLogger +{ + private readonly ExtendedLogger _parentLogger; + + public BufferedLoggerProxy(ExtendedLogger parentLogger) + { + _parentLogger = parentLogger; + } + + public void LogRecords(IEnumerable records) + { + LoggerInformation[] loggerInformations = _parentLogger.Loggers; + foreach (LoggerInformation loggerInformation in loggerInformations) + { + ILogger iLogger = loggerInformation.Logger; + if (iLogger is IBufferedLogger bufferedLogger) + { + bufferedLogger.LogRecords(records); + } + else + { + foreach (BufferedLogRecord record in records) + { +#pragma warning disable CA2201 // Do not raise reserved exception types + iLogger.Log( + record.LogLevel, + record.EventId, + record.Attributes, + record.Exception is not null ? new Exception(record.Exception) : null, + (_, _) => record.FormattedMessage ?? string.Empty); +#pragma warning restore CA2201 // Do not raise reserved exception types + } + } + } + } +} + +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs new file mode 100644 index 00000000000..64bd8ffe439 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs @@ -0,0 +1,185 @@ +// 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.Concurrent; +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.ObjectPool; +using Microsoft.Extensions.Options; +using Microsoft.Shared.Diagnostics; +using Microsoft.Shared.Pools; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +internal sealed class GlobalBuffer : IDisposable +{ + private const int MaxBatchSize = 256; + private static readonly ObjectPool> _recordsToEmitListPool = + PoolFactory.CreateListPoolWithCapacity(MaxBatchSize); + + private readonly IOptionsMonitor _options; + private readonly IBufferedLogger _bufferedLogger; + private readonly TimeProvider _timeProvider; + private readonly LogBufferingFilterRuleSelector _ruleSelector; + private readonly IDisposable? _optionsChangeTokenRegistration; + private readonly string _category; + private readonly Lock _bufferSwapLock = new(); + + private ConcurrentQueue _activeBuffer = new(); + private ConcurrentQueue _standbyBuffer = new(); + + private DateTimeOffset _lastFlushTimestamp; + private int _activeBufferSize; + private LogBufferingFilterRule[] _lastKnownGoodFilterRules; + + private volatile bool _disposed; + + public GlobalBuffer( + IBufferedLogger bufferedLogger, + string category, + LogBufferingFilterRuleSelector ruleSelector, + IOptionsMonitor options, + TimeProvider timeProvider) + { + _options = Throw.IfNull(options); + _timeProvider = timeProvider; + _bufferedLogger = bufferedLogger; + _category = Throw.IfNullOrEmpty(category); + _ruleSelector = Throw.IfNull(ruleSelector); + _lastKnownGoodFilterRules = LogBufferingFilterRuleSelector.SelectByCategory(_options.CurrentValue.Rules.ToArray(), _category); + _optionsChangeTokenRegistration = options.OnChange(OnOptionsChanged); + } + + public void Dispose() + { + if (_disposed) + { + return; + } + + _disposed = true; + + _optionsChangeTokenRegistration?.Dispose(); + } + + public bool TryEnqueue(LogEntry logEntry) + { + if (_timeProvider.GetUtcNow() < _lastFlushTimestamp + _options.CurrentValue.AutoFlushDuration) + { + return false; + } + + IReadOnlyList>? attributes = logEntry.State as IReadOnlyList>; + if (attributes is null) + { + // we expect state to be either ModernTagJoiner or LegacyTagJoiner + // which both implement IReadOnlyList> + // and if not, we throw an exception + Throw.InvalidOperationException( + $"Unsupported type of log state detected: {typeof(TState)}, expected IReadOnlyList>"); + } + + if (_ruleSelector.Select(_lastKnownGoodFilterRules, logEntry.LogLevel, logEntry.EventId, attributes) is null) + { + // buffering is not enabled for this log entry, + // return false to indicate that the log entry should be logged normally. + return false; + } + + SerializedLogRecord serializedLogRecord = SerializedLogRecordFactory.Create( + logEntry.LogLevel, + logEntry.EventId, + _timeProvider.GetUtcNow(), + attributes, + logEntry.Exception, + logEntry.Formatter(logEntry.State, logEntry.Exception)); + + if (serializedLogRecord.SizeInBytes > _options.CurrentValue.MaxLogRecordSizeInBytes) + { + SerializedLogRecordFactory.Return(serializedLogRecord); + return false; + } + + lock (_bufferSwapLock) + { + _activeBuffer.Enqueue(serializedLogRecord); + _ = Interlocked.Add(ref _activeBufferSize, serializedLogRecord.SizeInBytes); + } + + TrimExcessRecords(); + + return true; + } + + public void Flush() + { + _lastFlushTimestamp = _timeProvider.GetUtcNow(); + + ConcurrentQueue tempBuffer; + int numItemsToEmit; + lock (_bufferSwapLock) + { + tempBuffer = _activeBuffer; + _activeBuffer = _standbyBuffer; + _standbyBuffer = tempBuffer; + + numItemsToEmit = tempBuffer.Count; + + _ = Interlocked.Exchange(ref _activeBufferSize, 0); + } + + for (int offset = 0; offset < numItemsToEmit && !tempBuffer.IsEmpty; offset += MaxBatchSize) + { + int currentBatchSize = Math.Min(MaxBatchSize, numItemsToEmit - offset); + List recordsToEmit = _recordsToEmitListPool.Get(); + try + { + for (int i = 0; i < currentBatchSize && tempBuffer.TryDequeue(out SerializedLogRecord bufferedRecord); i++) + { + recordsToEmit.Add(new DeserializedLogRecord( + bufferedRecord.Timestamp, + bufferedRecord.LogLevel, + bufferedRecord.EventId, + bufferedRecord.Exception, + bufferedRecord.FormattedMessage, + bufferedRecord.Attributes)); + } + + _bufferedLogger.LogRecords(recordsToEmit); + } + finally + { + _recordsToEmitListPool.Return(recordsToEmit); + } + } + } + + private void OnOptionsChanged(GlobalLogBufferingOptions? updatedOptions) + { + if (updatedOptions is null) + { + _lastKnownGoodFilterRules = []; + } + else + { + _lastKnownGoodFilterRules = LogBufferingFilterRuleSelector.SelectByCategory(updatedOptions.Rules.ToArray(), _category); + } + + _ruleSelector.InvalidateCache(); + } + + private void TrimExcessRecords() + { + while (_activeBufferSize > _options.CurrentValue.MaxBufferSizeInBytes && + _activeBuffer.TryDequeue(out SerializedLogRecord item)) + { + _ = Interlocked.Add(ref _activeBufferSize, -item.SizeInBytes); + SerializedLogRecordFactory.Return(item); + } + } +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggingBuilderExtensions.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggingBuilderExtensions.cs new file mode 100644 index 00000000000..bf06c546566 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggingBuilderExtensions.cs @@ -0,0 +1,104 @@ +// 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.Diagnostics.CodeAnalysis; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; +using Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Options; +using Microsoft.Shared.DiagnosticIds; +using Microsoft.Shared.Diagnostics; + +namespace Microsoft.Extensions.Logging; + +/// +/// Lets you register log buffering in a dependency injection container. +/// +[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] +public static class GlobalBufferLoggingBuilderExtensions +{ + /// + /// Adds global log buffering to the logging infrastructure. + /// + /// The . + /// The to add. + /// The value of . + /// is . + /// + /// Matched logs will be buffered and can optionally be flushed and emitted. + /// + public static ILoggingBuilder AddGlobalBuffer(this ILoggingBuilder builder, IConfiguration configuration) + { + _ = Throw.IfNull(builder); + _ = Throw.IfNull(configuration); + + _ = builder + .Services.AddOptionsWithValidateOnStart() + .Services.AddOptionsWithValidateOnStart() + .Services.AddSingleton>(new GlobalLogBufferingConfigureOptions(configuration)); + + return builder.AddGlobalBufferManager(); + } + + /// + /// Adds global log buffering to the logging infrastructure. + /// + /// The . + /// Configure buffer options. + /// The value of . + /// is . + /// + /// Matched logs will be buffered and can optionally be flushed and emitted. + /// + public static ILoggingBuilder AddGlobalBuffer(this ILoggingBuilder builder, Action configure) + { + _ = Throw.IfNull(builder); + _ = Throw.IfNull(configure); + + _ = builder + .Services.AddOptionsWithValidateOnStart() + .Services.AddOptionsWithValidateOnStart() + .Configure(configure); + + return builder.AddGlobalBufferManager(); + } + + /// + /// Adds global log buffering to the logging infrastructure. + /// + /// The . + /// The log level (and below) to apply the buffer to. + /// The value of . + /// is . + /// + /// Matched logs will be buffered and can optionally be flushed and emitted. + /// + public static ILoggingBuilder AddGlobalBuffer(this ILoggingBuilder builder, LogLevel? logLevel = null) + { + _ = Throw.IfNull(builder); + + _ = builder + .Services.AddOptionsWithValidateOnStart() + .Services.AddOptionsWithValidateOnStart() + .Configure(options => options.Rules.Add(new LogBufferingFilterRule(logLevel: logLevel))); + + return builder.AddGlobalBufferManager(); + } + + private static ILoggingBuilder AddGlobalBufferManager(this ILoggingBuilder builder) + { + _ = builder.Services.AddExtendedLoggerFeactory(); + + builder.Services.TryAddSingleton(); + builder.Services.TryAddSingleton(); + builder.Services.TryAddSingleton(static sp => sp.GetRequiredService()); + builder.Services.TryAddSingleton(static sp => sp.GetRequiredService()); + + return builder; + } +} + +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferManager.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferManager.cs new file mode 100644 index 00000000000..8cc25fe3a7c --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferManager.cs @@ -0,0 +1,56 @@ +// 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.Concurrent; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Options; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +internal sealed class GlobalLogBufferManager : GlobalLogBuffer +{ + private readonly ConcurrentDictionary _buffers = []; + private readonly IOptionsMonitor _options; + private readonly TimeProvider _timeProvider; + private readonly LogBufferingFilterRuleSelector _ruleSelector; + + public GlobalLogBufferManager( + LogBufferingFilterRuleSelector ruleSelector, + IOptionsMonitor options) + : this(ruleSelector, options, TimeProvider.System) + { + } + + internal GlobalLogBufferManager( + LogBufferingFilterRuleSelector ruleSelector, + IOptionsMonitor options, + TimeProvider timeProvider) + { + _ruleSelector = ruleSelector; + _options = options; + _timeProvider = timeProvider; + } + + public override void Flush() + { + foreach (GlobalBuffer buffer in _buffers.Values) + { + buffer.Flush(); + } + } + + public override bool TryEnqueue(IBufferedLogger bufferedLogger, in LogEntry logEntry) + { + string category = logEntry.Category; + GlobalBuffer buffer = _buffers.GetOrAdd(category, _ => new GlobalBuffer( + bufferedLogger, + category, + _ruleSelector, + _options, + _timeProvider)); + return buffer.TryEnqueue(logEntry); + } +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingConfigureOptions.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingConfigureOptions.cs new file mode 100644 index 00000000000..0d7c048497a --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingConfigureOptions.cs @@ -0,0 +1,49 @@ +// 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 Microsoft.Extensions.Configuration; +using Microsoft.Extensions.Options; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +internal sealed class GlobalLogBufferingConfigureOptions : IConfigureOptions +{ + private const string ConfigSectionName = "GlobalLogBuffering"; + private readonly IConfiguration _configuration; + + public GlobalLogBufferingConfigureOptions(IConfiguration configuration) + { + _configuration = configuration; + } + + public void Configure(GlobalLogBufferingOptions options) + { + if (_configuration is null) + { + return; + } + + IConfigurationSection section = _configuration.GetSection(ConfigSectionName); + if (!section.Exists()) + { + return; + } + + GlobalLogBufferingOptions? parsedOptions = section.Get(); + if (parsedOptions is null) + { + return; + } + + options.MaxLogRecordSizeInBytes = parsedOptions.MaxLogRecordSizeInBytes; + options.MaxBufferSizeInBytes = parsedOptions.MaxBufferSizeInBytes; + options.AutoFlushDuration = parsedOptions.AutoFlushDuration; + + foreach (LogBufferingFilterRule rule in parsedOptions.Rules) + { + options.Rules.Add(rule); + } + } +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptions.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptions.cs new file mode 100644 index 00000000000..89a0bf0aa84 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptions.cs @@ -0,0 +1,78 @@ +// 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.Generic; +using System.ComponentModel.DataAnnotations; +using System.Diagnostics.CodeAnalysis; +using Microsoft.Shared.Data.Validation; +using Microsoft.Shared.DiagnosticIds; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +/// +/// The options for global log buffering. +/// +[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] +public class GlobalLogBufferingOptions +{ + private const int DefaultMaxBufferSizeInBytes = 500 * 1024 * 1024; // 500 MB. + private const int DefaultMaxLogRecordSizeInBytes = 50 * 1024; // 50 KB. + + private const int MinimumAutoFlushDuration = 0; + private const int MaximumAutoFlushDuration = 1000 * 60 * 60 * 24; // 1 day. + + private const long MinimumBufferSizeInBytes = 1; + private const long MaximumBufferSizeInBytes = 10L * 1024 * 1024 * 1024; // 10 GB. + + private const long MinimumLogRecordSizeInBytes = 1; + private const long MaximumLogRecordSizeInBytes = 10 * 1024 * 1024; // 10 MB. + + private static readonly TimeSpan _defaultAutoFlushDuration = TimeSpan.FromSeconds(30); + + /// + /// Gets or sets the time to do automatic flushing after manual flushing was triggered. + /// + /// + /// Use this to temporarily suspend buffering after a flush, e.g. in case of an incident you may want all logs to be emitted immediately, + /// so the buffering will be suspended for the time. + /// + [TimeSpan(MinimumAutoFlushDuration, MaximumAutoFlushDuration)] + public TimeSpan AutoFlushDuration { get; set; } = _defaultAutoFlushDuration; + + /// + /// Gets or sets the maximum size of each individual log record in bytes. + /// + /// + /// If the size of a log record exceeds this limit, it won't be buffered. + /// + [Range(MinimumLogRecordSizeInBytes, MaximumLogRecordSizeInBytes)] + public int MaxLogRecordSizeInBytes { get; set; } = DefaultMaxLogRecordSizeInBytes; + + /// + /// Gets or sets the maximum size of the buffer in bytes. + /// + /// + /// If adding a new log entry would cause the buffer size to exceed this limit, + /// the oldest buffered log records will be dropped to make room. + /// + [Range(MinimumBufferSizeInBytes, MaximumBufferSizeInBytes)] + public int MaxBufferSizeInBytes { get; set; } = DefaultMaxBufferSizeInBytes; + +#pragma warning disable CA2227 // Collection properties should be read only - setter is necessary for options pattern. + /// + /// Gets or sets the collection of used for filtering log messages for the purpose of further buffering. + /// + /// + /// If a log entry matches a rule, it will be buffered. Consequently, it will later be emitted when the buffer is flushed. + /// If a log entry does not match any rule, it will be emitted normally. + /// If the buffer size limit is reached, the oldest buffered log entries will be dropped (not emitted!) to make room for new ones. + /// If a log entry size is greater than , it will not be buffered and will be emitted normally. + /// + [Required] + public IList Rules { get; set; } = []; +#pragma warning restore CA2227 +} + +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptionsCustomValidator.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptionsCustomValidator.cs new file mode 100644 index 00000000000..d3490b8e6a2 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptionsCustomValidator.cs @@ -0,0 +1,34 @@ +// 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 Microsoft.Extensions.Options; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +internal sealed class GlobalLogBufferingOptionsCustomValidator : IValidateOptions +{ + private const char WildcardChar = '*'; + + public ValidateOptionsResult Validate(string? name, GlobalLogBufferingOptions options) + { + ValidateOptionsResultBuilder resultBuilder = new(); + foreach (LogBufferingFilterRule rule in options.Rules) + { + if (rule.CategoryName is null) + { + continue; + } + + int wildcardIndex = rule.CategoryName.IndexOf(WildcardChar, StringComparison.Ordinal); + if (wildcardIndex >= 0 && rule.CategoryName.IndexOf(WildcardChar, wildcardIndex + 1) >= 0) + { + resultBuilder.AddError("Only one wildcard character is allowed in category name.", nameof(options.Rules)); + } + } + + return resultBuilder.Build(); + } +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptionsValidator.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptionsValidator.cs new file mode 100644 index 00000000000..0edb4fb5d41 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalLogBufferingOptionsValidator.cs @@ -0,0 +1,13 @@ +// 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 Microsoft.Extensions.Options; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +[OptionsValidator] +internal sealed partial class GlobalLogBufferingOptionsValidator : IValidateOptions +{ +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/LogBufferingFilterRule.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/LogBufferingFilterRule.cs new file mode 100644 index 00000000000..6aa0a0109fa --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/LogBufferingFilterRule.cs @@ -0,0 +1,71 @@ +// 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.Collections.Generic; +using System.Diagnostics.CodeAnalysis; +using Microsoft.Extensions.Logging; +using Microsoft.Shared.DiagnosticIds; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +/// +/// Defines a rule used to filter log messages for purposes of further buffering. +/// +/// +/// If a log entry matches a rule, it will be buffered. Consequently, it will later be emitted when the buffer is flushed. +/// If a log entry does not match any rule, it will be emitted normally. +/// If the buffer size limit is reached, the oldest buffered log entries will be dropped (not emitted!) to make room for new ones. +/// +[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] +public class LogBufferingFilterRule +{ + /// + /// Initializes a new instance of the class. + /// + /// The category name to use in this filter rule. + /// The to use in this filter rule. + /// The event ID to use in this filter rule. + /// The event name to use in this filter rule. + /// The log state attributes to use in this filter rule. + public LogBufferingFilterRule( + string? categoryName = null, + LogLevel? logLevel = null, + int? eventId = null, + string? eventName = null, + IReadOnlyList>? attributes = null) + { + CategoryName = categoryName; + LogLevel = logLevel; + EventId = eventId; + EventName = eventName; + Attributes = attributes; + } + + /// + /// Gets the logger category name this rule applies to. + /// + public string? CategoryName { get; } + + /// + /// Gets the maximum of messages this rule applies to. + /// + public LogLevel? LogLevel { get; } + + /// + /// Gets the event ID of messages where this rule applies to. + /// + public int? EventId { get; } + + /// + /// Gets the name of the event this rule applies to. + /// + public string? EventName { get; } + + /// + /// Gets the log state attributes of messages where this rule applies to. + /// + public IReadOnlyList>? Attributes { get; } +} + +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/LogBufferingFilterRuleSelector.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/LogBufferingFilterRuleSelector.cs new file mode 100644 index 00000000000..09e4b3c9025 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/LogBufferingFilterRuleSelector.cs @@ -0,0 +1,185 @@ +// 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 + +#pragma warning disable CA1307 // Specify StringComparison for clarity +#pragma warning disable S1659 // Multiple variables should not be declared on the same line +#pragma warning disable S2302 // "nameof" should be used + +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Linq; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.ObjectPool; +using Microsoft.Shared.Pools; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +/// +/// Selects the best rule from the list of rules for a given log event. +/// +internal sealed class LogBufferingFilterRuleSelector +{ + private static readonly IEqualityComparer> _stringifyComparer = new StringifyComprarer(); + private static readonly ObjectPool> _rulePool = + PoolFactory.CreateListPool(); + + private readonly ObjectPool> _cachedRulePool = + PoolFactory.CreateListPool(); + private readonly ConcurrentDictionary<(LogLevel, EventId), List> _ruleCache = new(); + + public static LogBufferingFilterRule[] SelectByCategory(IList rules, string category) + { + List rulesOfCategory = _rulePool.Get(); + try + { + // Select rules with applicable category only + foreach (LogBufferingFilterRule rule in rules) + { + if (IsMatch(rule, category)) + { + rulesOfCategory.Add(rule); + } + } + + return rulesOfCategory.ToArray(); + } + finally + { + _rulePool.Return(rulesOfCategory); + } + } + + public void InvalidateCache() + { + foreach (((LogLevel, EventId) key, List value) in _ruleCache) + { + _cachedRulePool.Return(value); + } + + _ruleCache.Clear(); + } + + public LogBufferingFilterRule? Select( + IList rules, + LogLevel logLevel, + EventId eventId, + IReadOnlyList>? attributes) + { + // 1. select rule candidates by log level and event id from the cache + List ruleCandidates = _ruleCache.GetOrAdd((logLevel, eventId), _ => + { + List candidates = _cachedRulePool.Get(); + foreach (LogBufferingFilterRule rule in rules) + { + if (IsMatch(rule, logLevel, eventId)) + { + candidates.Add(rule); + } + } + + return candidates; + }); + + // 2. select the best rule from the candidates by attributes + LogBufferingFilterRule? currentBest = null; + foreach (LogBufferingFilterRule ruleCandidate in ruleCandidates) + { + if (IsAttributesMatch(ruleCandidate, attributes) && IsBetter(currentBest, ruleCandidate)) + { + currentBest = ruleCandidate; + } + } + + return currentBest; + } + + private static bool IsAttributesMatch(LogBufferingFilterRule rule, IReadOnlyList>? attributes) + { + // Skip rules with inapplicable attributes + if (rule.Attributes?.Count > 0 && attributes?.Count > 0) + { + foreach (KeyValuePair ruleAttribute in rule.Attributes) + { + if (!attributes.Contains(ruleAttribute, _stringifyComparer)) + { + return false; + } + } + } + + return true; + } + + private static bool IsBetter(LogBufferingFilterRule? currentBest, LogBufferingFilterRule ruleCandidate) + { + // Decide whose attributes are better - rule vs current + if (currentBest?.Attributes?.Count > 0) + { + if (ruleCandidate.Attributes is null || ruleCandidate.Attributes.Count == 0) + { + return false; + } + + if (ruleCandidate.Attributes.Count < currentBest.Attributes.Count) + { + return false; + } + } + + return true; + } + + private static bool IsMatch(LogBufferingFilterRule rule, string category) + { + const char WildcardChar = '*'; + + string? ruleCategory = rule.CategoryName; + if (ruleCategory is null) + { + return true; + } + + int wildcardIndex = ruleCategory.IndexOf(WildcardChar); + + ReadOnlySpan prefix, suffix; + if (wildcardIndex == -1) + { + prefix = ruleCategory.AsSpan(); + suffix = default; + } + else + { + prefix = ruleCategory.AsSpan(0, wildcardIndex); + suffix = ruleCategory.AsSpan(wildcardIndex + 1); + } + + if (!category.AsSpan().StartsWith(prefix, StringComparison.OrdinalIgnoreCase) || + !category.AsSpan().EndsWith(suffix, StringComparison.OrdinalIgnoreCase)) + { + return false; + } + + return true; + } + + private static bool IsMatch(LogBufferingFilterRule rule, LogLevel logLevel, EventId eventId) + { + // Skip rules with inapplicable log level + if (rule.LogLevel is not null && rule.LogLevel < logLevel) + { + return false; + } + + // Skip rules with inapplicable event id + if (rule.EventId is not null && rule.EventId != eventId) + { + return false; + } + + return true; + } +} + +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/StringifyComprarer.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/StringifyComprarer.cs new file mode 100644 index 00000000000..fbec3961880 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/StringifyComprarer.cs @@ -0,0 +1,35 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Generic; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +internal sealed class StringifyComprarer : IEqualityComparer> +{ + public bool Equals(KeyValuePair x, KeyValuePair y) + { + if (x.Key != y.Key) + { + return false; + } + + if (x.Value is null && y.Value is null) + { + return true; + } + + if (x.Value is null || y.Value is null) + { + return false; + } + + return x.Value.ToString() == y.Value.ToString(); + } + + public int GetHashCode(KeyValuePair obj) + { + return HashCode.Combine(obj.Key, obj.Value?.ToString()); + } +} diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs index b36a7e0edac..162923d055c 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs @@ -4,6 +4,9 @@ using System; using System.Collections.Generic; using System.Diagnostics; +#if NET9_0_OR_GREATER +using Microsoft.Extensions.Diagnostics.Buffering; +#endif using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Shared.Pools; @@ -30,11 +33,22 @@ internal sealed partial class ExtendedLogger : ILogger public LoggerInformation[] Loggers { get; set; } public MessageLogger[] MessageLoggers { get; set; } = Array.Empty(); public ScopeLogger[] ScopeLoggers { get; set; } = Array.Empty(); +#if NET9_0_OR_GREATER + private readonly LogBuffer? _logBuffer; + private readonly IBufferedLogger? _bufferedLogger; +#endif public ExtendedLogger(ExtendedLoggerFactory factory, LoggerInformation[] loggers) { _factory = factory; Loggers = loggers; +#if NET9_0_OR_GREATER + _logBuffer = _factory.Config.LogBuffer; + if (_logBuffer is not null) + { + _bufferedLogger = new BufferedLoggerProxy(this); + } +#endif } public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) @@ -261,27 +275,66 @@ private void ModernPath(LogLevel logLevel, EventId eventId, LoggerMessageState m RecordException(exception, joiner.EnrichmentTagCollector, config); } - bool? samplingDecision = null; + bool? shouldSample = null; +#if NET9_0_OR_GREATER + bool shouldBuffer = true; +#endif for (int i = 0; i < loggers.Length; i++) { ref readonly MessageLogger loggerInfo = ref loggers[i]; if (loggerInfo.IsNotFilteredOut(logLevel)) { - if (samplingDecision is null && config.Sampler is not null) + if (shouldSample is null && config.Sampler is not null) { - var logEntry = new LogEntry(logLevel, loggerInfo.Category, eventId, joiner, exception, static (s, e) => - { - Func fmt = s.Formatter!; - return fmt(s.State!, e); - }); - samplingDecision = config.Sampler.ShouldSample(in logEntry); + var logEntry = new LogEntry( + logLevel, + loggerInfo.Category, + eventId, + joiner, + exception, + static (s, e) => + { + Func fmt = s.Formatter!; + return fmt(s.State!, e); + }); + + shouldSample = config.Sampler.ShouldSample(in logEntry); } - if (samplingDecision is false) + if (shouldSample is false) { - // the record was not selected for being sampled in, so we drop it. + // the record was not selected for being sampled in, so we drop it for all loggers. break; } +#if NET9_0_OR_GREATER + if (shouldBuffer) + { + if (_logBuffer is not null) + { + var logEntry = new LogEntry( + logLevel, + loggerInfo.Category, + eventId, + joiner, + exception, + static (s, e) => + { + Func? fmt = s.Formatter!; + return fmt(s.State!, e); + }); + + if (_logBuffer.TryEnqueue(_bufferedLogger!, logEntry)) + { + // The record was buffered, so we skip logging it here and for all other loggers. + // When a caller needs to flush the buffer and calls Flush(), + // the buffer manager will internally call IBufferedLogger.LogRecords to emit log records. + break; + } + } + + shouldBuffer = false; + } +#endif try { @@ -362,28 +415,67 @@ private void LegacyPath(LogLevel logLevel, EventId eventId, TState state break; } - bool? samplingDecision = null; + bool? shouldSample = null; +#if NET9_0_OR_GREATER + bool shouldBuffer = true; +#endif for (int i = 0; i < loggers.Length; i++) { ref readonly MessageLogger loggerInfo = ref loggers[i]; if (loggerInfo.IsNotFilteredOut(logLevel)) { - if (samplingDecision is null && config.Sampler is not null) + if (shouldSample is null && config.Sampler is not null) { - var logEntry = new LogEntry(logLevel, loggerInfo.Category, eventId, joiner, exception, static (s, e) => - { - var fmt = (Func)s.Formatter!; - return fmt((TState)s.State!, e); - }); - samplingDecision = config.Sampler.ShouldSample(in logEntry); + var logEntry = new LogEntry( + logLevel, + loggerInfo.Category, + eventId, + joiner, + exception, + static (s, e) => + { + var fmt = (Func)s.Formatter!; + return fmt((TState)s.State!, e); + }); + + shouldSample = config.Sampler.ShouldSample(in logEntry); } - if (samplingDecision is false) + if (shouldSample is false) { // the record was not selected for being sampled in, so we drop it. break; } +#if NET9_0_OR_GREATER + if (shouldBuffer) + { + if (_logBuffer is not null) + { + var logEntry = new LogEntry( + logLevel, + loggerInfo.Category, + eventId, + joiner, + exception, + static (s, e) => + { + var fmt = (Func)s.Formatter!; + return fmt((TState)s.State!, e); + }); + + if (_logBuffer.TryEnqueue(_bufferedLogger!, in logEntry)) + { + // The record was buffered, so we skip logging it here and for all other loggers. + // When a caller needs to flush the buffer and calls Flush(), + // the buffer manager will internally call IBufferedLogger.LogRecords to emit log records. + break; + } + + } + shouldBuffer = false; + } +#endif try { loggerInfo.Logger.Log(logLevel, eventId, joiner, exception, static (s, e) => diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLoggerFactory.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLoggerFactory.cs index 32b711c2aae..44ec71b6f68 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLoggerFactory.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLoggerFactory.cs @@ -7,6 +7,9 @@ using System.Linq; using Microsoft.Extensions.Compliance.Classification; using Microsoft.Extensions.Compliance.Redaction; +#if NET9_0_OR_GREATER +using Microsoft.Extensions.Diagnostics.Buffering; +#endif using Microsoft.Extensions.Diagnostics.Enrichment; using Microsoft.Extensions.Options; using Microsoft.Shared.Diagnostics; @@ -24,6 +27,9 @@ internal sealed class ExtendedLoggerFactory : ILoggerFactory private readonly IDisposable? _redactionOptionsChangeTokenRegistration; private readonly Action[] _enrichers; private readonly LoggingSampler? _sampler; +#if NET9_0_OR_GREATER + private readonly LogBuffer? _logBuffer; +#endif private readonly KeyValuePair[] _staticTags; private readonly Func _redactorProvider; private volatile bool _disposed; @@ -41,10 +47,18 @@ public ExtendedLoggerFactory( IExternalScopeProvider? scopeProvider = null, IOptionsMonitor? enrichmentOptions = null, IOptionsMonitor? redactionOptions = null, +#if NET9_0_OR_GREATER + IRedactorProvider? redactorProvider = null, + LogBuffer? logBuffer = null) +#else IRedactorProvider? redactorProvider = null) +#endif #pragma warning restore S107 // Methods should not have too many parameters { _scopeProvider = scopeProvider; +#if NET9_0_OR_GREATER + _logBuffer = logBuffer; +#endif _sampler = sampler; _factoryOptions = factoryOptions == null || factoryOptions.Value == null ? new LoggerFactoryOptions() : factoryOptions.Value; @@ -293,13 +307,18 @@ private LoggerConfig ComputeConfig(LoggerEnrichmentOptions? enrichmentOptions, L enrichmentOptions.IncludeExceptionMessage, enrichmentOptions.MaxStackTraceLength, _redactorProvider, +#if NET9_0_OR_GREATER + redactionOptions.ApplyDiscriminator, + _logBuffer); +#else redactionOptions.ApplyDiscriminator); +#endif } private void UpdateEnrichmentOptions(LoggerEnrichmentOptions enrichmentOptions) => Config = ComputeConfig(enrichmentOptions, null); private void UpdateRedactionOptions(LoggerRedactionOptions redactionOptions) => Config = ComputeConfig(null, redactionOptions); - private struct ProviderRegistration + public struct ProviderRegistration { public ILoggerProvider Provider; public bool ShouldDispose; diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggerConfig.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggerConfig.cs index 12fc4708409..e4696e7f798 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggerConfig.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggerConfig.cs @@ -5,6 +5,9 @@ using System.Collections.Generic; using Microsoft.Extensions.Compliance.Classification; using Microsoft.Extensions.Compliance.Redaction; +#if NET9_0_OR_GREATER +using Microsoft.Extensions.Diagnostics.Buffering; +#endif using Microsoft.Extensions.Diagnostics.Enrichment; namespace Microsoft.Extensions.Logging; @@ -21,7 +24,12 @@ public LoggerConfig( bool includeExceptionMessage, int maxStackTraceLength, Func getRedactor, +#if NET9_0_OR_GREATER + bool addRedactionDiscriminator, + LogBuffer? logBuffer) +#else bool addRedactionDiscriminator) +#endif { #pragma warning restore S107 // Methods should not have too many parameters StaticTags = staticTags; @@ -33,6 +41,9 @@ public LoggerConfig( IncludeExceptionMessage = includeExceptionMessage; GetRedactor = getRedactor; AddRedactionDiscriminator = addRedactionDiscriminator; +#if NET9_0_OR_GREATER + LogBuffer = logBuffer; +#endif } public KeyValuePair[] StaticTags { get; } @@ -44,4 +55,7 @@ public LoggerConfig( public int MaxStackTraceLength { get; } public Func GetRedactor { get; } public bool AddRedactionDiscriminator { get; } +#if NET9_0_OR_GREATER + public LogBuffer? LogBuffer { get; } +#endif } diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggingEnrichmentExtensions.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggingEnrichmentExtensions.cs index 1d4262b454e..87563067283 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggingEnrichmentExtensions.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggingEnrichmentExtensions.cs @@ -34,9 +34,10 @@ public static ILoggingBuilder EnableEnrichment(this ILoggingBuilder builder, Act _ = Throw.IfNull(builder); _ = Throw.IfNull(configure); - builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); - _ = builder.Services.Configure(configure); - _ = builder.Services.AddOptionsWithValidateOnStart(); + _ = builder.Services + .AddExtendedLoggerFeactory() + .Configure(configure) + .AddOptionsWithValidateOnStart(); return builder; } @@ -52,9 +53,24 @@ public static ILoggingBuilder EnableEnrichment(this ILoggingBuilder builder, ICo _ = Throw.IfNull(builder); _ = Throw.IfNull(section); - builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); - _ = builder.Services.AddOptionsWithValidateOnStart().Bind(section); + _ = builder.Services + .AddExtendedLoggerFeactory() + .AddOptionsWithValidateOnStart().Bind(section); return builder; } + + /// + /// Adds a default implementation of the to the service collection. + /// + /// The . + /// The value of . + internal static IServiceCollection AddExtendedLoggerFeactory(this IServiceCollection services) + { + _ = Throw.IfNull(services); + + services.TryAddEnumerable(ServiceDescriptor.Singleton()); + + return services; + } } diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggingRedactionExtensions.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggingRedactionExtensions.cs index 4ec3ea9ef3e..284e24f10ea 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggingRedactionExtensions.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggingRedactionExtensions.cs @@ -4,7 +4,6 @@ using System; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.DependencyInjection.Extensions; using Microsoft.Extensions.Logging; using Microsoft.Shared.Diagnostics; @@ -34,8 +33,9 @@ public static ILoggingBuilder EnableRedaction(this ILoggingBuilder builder, Acti _ = Throw.IfNull(builder); _ = Throw.IfNull(configure); - builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); - _ = builder.Services.Configure(configure); + _ = builder.Services + .AddExtendedLoggerFeactory() + .Configure(configure); return builder; } @@ -51,8 +51,9 @@ public static ILoggingBuilder EnableRedaction(this ILoggingBuilder builder, ICon _ = Throw.IfNull(builder); _ = Throw.IfNull(section); - builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); - _ = builder.Services.AddOptions().Bind(section); + _ = builder.Services + .AddExtendedLoggerFeactory() + .AddOptions().Bind(section); return builder; } diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.csproj b/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.csproj index 46e815ccd80..81d379cd381 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.csproj +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.csproj @@ -10,15 +10,16 @@ true true true + true true + true + true true true true - true - true true true - + normal diff --git a/src/Shared/LogBuffering/DeserializedLogRecord.cs b/src/Shared/LogBuffering/DeserializedLogRecord.cs new file mode 100644 index 00000000000..898dc48ebf6 --- /dev/null +++ b/src/Shared/LogBuffering/DeserializedLogRecord.cs @@ -0,0 +1,65 @@ +// 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.Generic; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +/// +/// Represents a log record deserialized from somewhere, such as buffer. +/// +internal sealed class DeserializedLogRecord : BufferedLogRecord +{ + /// + /// Initializes a new instance of the class. + /// + /// The time when the log record was first created. + /// Logging severity level. + /// Event ID. + /// An exception string for this record. + /// The formatted log message. + /// The set of name/value pairs associated with the record. + public DeserializedLogRecord( + DateTimeOffset timestamp, + LogLevel logLevel, + EventId eventId, + string? exception, + string? formattedMessage, + IReadOnlyList> attributes) + { + _timestamp = timestamp; + _logLevel = logLevel; + _eventId = eventId; + _exception = exception; + _formattedMessage = formattedMessage; + _attributes = attributes; + } + + /// + public override DateTimeOffset Timestamp => _timestamp; + private DateTimeOffset _timestamp; + + /// + public override LogLevel LogLevel => _logLevel; + private LogLevel _logLevel; + + /// + public override EventId EventId => _eventId; + private EventId _eventId; + + /// + public override string? Exception => _exception; + private string? _exception; + + /// + public override string? FormattedMessage => _formattedMessage; + private string? _formattedMessage; + + /// + public override IReadOnlyList> Attributes => _attributes; + private IReadOnlyList> _attributes; +} +#endif diff --git a/src/Shared/LogBuffering/SerializedLogRecord.cs b/src/Shared/LogBuffering/SerializedLogRecord.cs new file mode 100644 index 00000000000..f17711b26d9 --- /dev/null +++ b/src/Shared/LogBuffering/SerializedLogRecord.cs @@ -0,0 +1,82 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Generic; +using System.Diagnostics; +using Microsoft.Extensions.Logging; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +/// +/// Represents a log record that has been serialized for purposes of buffering or similar. +/// +#pragma warning disable CA1815 // Override equals and operator equals on value types - not used for this struct, would be dead code +[DebuggerDisplay("Message: {FormattedMessage}, LogLevel:{LogLevel}, Timestamp: {Timestamp.ToString(FormatSpecifier)}")] +internal readonly struct SerializedLogRecord +{ + private const string FormatSpecifier = "u"; + + /// + /// Initializes a new instance of the struct. + /// + /// Logging severity level. + /// Event ID. + /// The time when the log record was first created. + /// The set of name/value pairs associated with the record. + /// An exception message for this record. + /// The formatted log message. + /// The approximate size in bytes of this instance. + public SerializedLogRecord( + LogLevel logLevel, + EventId eventId, + DateTimeOffset timestamp, + List> attributes, + string exceptionMessage, + string formattedMessage, + int sizeInBytes) + { + LogLevel = logLevel; + EventId = eventId; + Timestamp = timestamp; + Attributes = attributes; + Exception = exceptionMessage; + FormattedMessage = formattedMessage; + SizeInBytes = sizeInBytes; + } + + /// + /// Gets the record's logging severity level. + /// + public LogLevel LogLevel { get; } + + /// + /// Gets the record's event ID. + /// + public EventId EventId { get; } + + /// + /// Gets the time when the log record was first created. + /// + public DateTimeOffset Timestamp { get; } + + /// + /// Gets the variable set of name/value pairs associated with the record. + /// + public List> Attributes { get; } + + /// + /// Gets an exception string for this record. + /// + public string? Exception { get; } + + /// + /// Gets the formatted log message. + /// + public string? FormattedMessage { get; } + + /// + /// Gets the approximate size of the serialized log record in bytes. + /// + public int SizeInBytes { get; } +} diff --git a/src/Shared/LogBuffering/SerializedLogRecordFactory.cs b/src/Shared/LogBuffering/SerializedLogRecordFactory.cs new file mode 100644 index 00000000000..288c6532a46 --- /dev/null +++ b/src/Shared/LogBuffering/SerializedLogRecordFactory.cs @@ -0,0 +1,83 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System; +using System.Collections.Generic; +using System.Runtime.CompilerServices; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.ObjectPool; +using Microsoft.Shared.Pools; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +internal static class SerializedLogRecordFactory +{ + private static readonly ObjectPool>> _attributesPool = + PoolFactory.CreateListPool>(); + + private static readonly int _serializedLogRecordSize = Unsafe.SizeOf(); + + public static SerializedLogRecord Create( + LogLevel logLevel, + EventId eventId, + DateTimeOffset timestamp, + IReadOnlyList> attributes, + Exception? exception, + string formattedMessage) + { + int sizeInBytes = _serializedLogRecordSize; + List> serializedAttributes = _attributesPool.Get(); + for (int i = 0; i < attributes.Count; i++) + { + string key = attributes[i].Key; + string value = attributes[i].Value?.ToString() ?? string.Empty; + + // deliberately not counting the size of the key, + // as it is constant strings in the vast majority of cases + + sizeInBytes += CalculateStringSize(value); + + serializedAttributes.Add(new KeyValuePair(key, value)); + } + + string exceptionMessage = string.Empty; + if (exception is not null) + { + exceptionMessage = exception.Message; + sizeInBytes += CalculateStringSize(exceptionMessage); + } + + sizeInBytes += CalculateStringSize(formattedMessage); + + return new SerializedLogRecord( + logLevel, + eventId, + timestamp, + serializedAttributes, + exceptionMessage, + formattedMessage, + sizeInBytes); + } + + public static void Return(SerializedLogRecord bufferedRecord) + { + _attributesPool.Return(bufferedRecord.Attributes); + } + + private static int CalculateStringSize(string str) + { + if (string.IsNullOrEmpty(str)) + { + return 0; + } + + // Base size: object overhead (16 bytes) + other stuff. + const int BaseSize = 26; + + // Strings are aligned to 8-byte boundaries + const int Alignment = 7; + + int charSize = str.Length * sizeof(char); + return (BaseSize + charSize + Alignment) & ~Alignment; + } +} diff --git a/src/Shared/Pools/PoolFactory.cs b/src/Shared/Pools/PoolFactory.cs index b3ecebea5ce..0d1f2352cbe 100644 --- a/src/Shared/Pools/PoolFactory.cs +++ b/src/Shared/Pools/PoolFactory.cs @@ -118,6 +118,25 @@ public static ObjectPool> CreateListPool(int maxCapacity = DefaultCap return MakePool(PooledListPolicy.Instance, maxCapacity); } + /// + /// Creates an object pool of instances, each with provided . + /// + /// The type of object held by the lists. + /// The capacity of each created instance. + /// + /// The maximum number of items to keep in the pool. + /// This defaults to 1024. + /// This value is a recommendation, the pool may keep more objects than this. + /// + /// The pool. + public static ObjectPool> CreateListPoolWithCapacity(int listCapacity, int maxCapacity = DefaultCapacity) + { + _ = Throw.IfLessThan(maxCapacity, 1); + _ = Throw.IfLessThan(listCapacity, 0); + + return MakePool(PooledListWithCapacityPolicy.Instance(listCapacity), maxCapacity); + } + /// /// Creates an object pool of instances. /// diff --git a/src/Shared/Pools/PooledListWithCapacityPolicy.cs b/src/Shared/Pools/PooledListWithCapacityPolicy.cs new file mode 100644 index 00000000000..c4f59e9c3a2 --- /dev/null +++ b/src/Shared/Pools/PooledListWithCapacityPolicy.cs @@ -0,0 +1,30 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Collections.Generic; +using Microsoft.Extensions.ObjectPool; + +namespace Microsoft.Shared.Pools; + +/// +/// An object pool policy for lists with capacity. +/// +[System.Diagnostics.CodeAnalysis.ExcludeFromCodeCoverage] +internal sealed class PooledListWithCapacityPolicy : PooledObjectPolicy> +{ + private readonly int _listCapacity; + public static PooledListWithCapacityPolicy Instance(int listCapacity) => new(listCapacity); + + private PooledListWithCapacityPolicy(int listCapacity) + { + _listCapacity = listCapacity; + } + + public override List Create() => new(_listCapacity); + + public override bool Return(List obj) + { + obj.Clear(); + return true; + } +} diff --git a/src/Shared/Shared.csproj b/src/Shared/Shared.csproj index 439c3788557..d25c011a05f 100644 --- a/src/Shared/Shared.csproj +++ b/src/Shared/Shared.csproj @@ -29,6 +29,7 @@ + diff --git a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerIncomingRequestLoggingBuilderExtensionsTests.cs b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerIncomingRequestLoggingBuilderExtensionsTests.cs new file mode 100644 index 00000000000..31ea8b45d4a --- /dev/null +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerIncomingRequestLoggingBuilderExtensionsTests.cs @@ -0,0 +1,86 @@ +// 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.Generic; +using Microsoft.AspNetCore.Diagnostics.Buffering; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Options; +using Xunit; +using PerRequestLogBuffer = Microsoft.Extensions.Diagnostics.Buffering.PerRequestLogBuffer; + +namespace Microsoft.Extensions.Logging; + +public class PerIncomingRequestLoggingBuilderExtensionsTests +{ + [Fact] + public void WhenLogLevelProvided_RegistersInDI() + { + var serviceCollection = new ServiceCollection(); + serviceCollection.AddLogging(builder => + { + builder.AddPerIncomingRequestBuffer(LogLevel.Warning); + }); + + ServiceProvider serviceProvider = serviceCollection.BuildServiceProvider(); + var buffer = serviceProvider.GetService(); + + Assert.NotNull(buffer); + Assert.IsAssignableFrom(buffer); + } + + [Fact] + public void WhenArgumentNull_Throws() + { + ILoggingBuilder? builder = null; + IConfiguration? configuration = null; + + Assert.Throws(() => builder!.AddPerIncomingRequestBuffer(LogLevel.Warning)); + Assert.Throws(() => builder!.AddPerIncomingRequestBuffer(configuration!)); + } + + [Fact] + public void WhenIConfigurationProvided_RegistersInDI() + { + List expectedData = + [ + new(categoryName: "Program.MyLogger", logLevel: LogLevel.Information, eventId: 1, eventName: "number one"), + new(logLevel: LogLevel.Information), + ]; + var configBuilder = new ConfigurationBuilder(); + configBuilder.AddJsonFile("appsettings.json"); + IConfigurationRoot configuration = configBuilder.Build(); + var serviceCollection = new ServiceCollection(); + serviceCollection.AddLogging(b => b.AddPerIncomingRequestBuffer(configuration)); + ServiceProvider serviceProvider = serviceCollection.BuildServiceProvider(); + var options = serviceProvider.GetService>(); + Assert.NotNull(options); + Assert.NotNull(options.CurrentValue); + Assert.Equivalent(expectedData, options.CurrentValue.Rules); + } + + [Fact] + public void WhenConfigurationActionProvided_RegistersInDI() + { + List expectedData = + [ + new(categoryName: "Program.MyLogger", logLevel: LogLevel.Information, eventId: 1, eventName: "number one"), + new(logLevel: LogLevel.Information), + ]; + var serviceCollection = new ServiceCollection(); + serviceCollection.AddLogging(b => b.AddPerIncomingRequestBuffer(options => + { + options.Rules.Add(new LogBufferingFilterRule(categoryName: "Program.MyLogger", + logLevel: LogLevel.Information, eventId: 1, eventName: "number one")); + options.Rules.Add(new LogBufferingFilterRule(logLevel: LogLevel.Information)); + })); + ServiceProvider serviceProvider = serviceCollection.BuildServiceProvider(); + var options = serviceProvider.GetService>(); + Assert.NotNull(options); + Assert.NotNull(options.CurrentValue); + Assert.Equivalent(expectedData, options.CurrentValue.Rules); + } +} +#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 new file mode 100644 index 00000000000..15431fa3bdb --- /dev/null +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingOptionsConfigureOptionsTests.cs @@ -0,0 +1,127 @@ +// 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.Collections.Generic; +using Microsoft.AspNetCore.Diagnostics.Buffering; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace Microsoft.Extensions.Diagnostics.Buffering.Test; + +public class PerRequestLogBufferingOptionsConfigureOptionsTests +{ + [Fact] + public void Configure_WhenConfigurationIsNull_DoesNotModifyOptions() + { + // Arrange + var options = new PerRequestLogBufferingOptions(); + var configureOptions = new PerRequestLogBufferingConfigureOptions(null!); + + // Act + configureOptions.Configure(options); + + // Assert + Assert.Equivalent(new PerRequestLogBufferingOptions(), options); + } + + [Fact] + public void Configure_WhenSectionDoesNotExist_DoesNotModifyOptions() + { + // Arrange + var options = new PerRequestLogBufferingOptions(); + IConfigurationRoot configuration = new ConfigurationBuilder().Build(); + var configureOptions = new PerRequestLogBufferingConfigureOptions(configuration); + + // Act + configureOptions.Configure(options); + + // Assert + Assert.Equivalent(new PerRequestLogBufferingOptions(), options); + } + + [Fact] + public void Configure_WhenSectionContainsInvalidPropertyNames_DoesNotModifyOptions() + { + // Arrange + var configValues = new Dictionary + { + ["GlobalLogBuffering"] = "1", + }; + + IConfigurationRoot configuration = new ConfigurationBuilder() + .AddInMemoryCollection(configValues) + .Build(); + + var options = new PerRequestLogBufferingOptions(); + var configureOptions = new PerRequestLogBufferingConfigureOptions(configuration); + + // Act + configureOptions.Configure(options); + + // Assert + Assert.Equivalent(new PerRequestLogBufferingOptions(), options); + } + + [Fact] + public void Configure_WithValidConfiguration_UpdatesOptions() + { + // Arrange + var configValues = new Dictionary + { + ["PerIncomingRequestLogBuffering:MaxLogRecordSizeInBytes"] = "1024", + ["PerIncomingRequestLogBuffering:MaxPerRequestBufferSizeInBytes"] = "4096", + ["PerIncomingRequestLogBuffering:Rules:0:CategoryName"] = "TestCategory", + ["PerIncomingRequestLogBuffering:Rules:0:LogLevel"] = "Information" + }; + + IConfigurationRoot configuration = new ConfigurationBuilder() + .AddInMemoryCollection(configValues) + .Build(); + + var options = new PerRequestLogBufferingOptions(); + var configureOptions = new PerRequestLogBufferingConfigureOptions(configuration); + + // Act + configureOptions.Configure(options); + + // Assert + Assert.Equal(1024, options.MaxLogRecordSizeInBytes); + Assert.Equal(4096, options.MaxPerRequestBufferSizeInBytes); + Assert.Single(options.Rules); + Assert.Equal("TestCategory", options.Rules[0].CategoryName); + Assert.Equal(LogLevel.Information, options.Rules[0].LogLevel); + } + + [Fact] + public void Configure_WithMultipleRules_AddsAllRules() + { + // Arrange + var configValues = new Dictionary + { + ["PerIncomingRequestLogBuffering:Rules:0:CategoryName"] = "Category1", + ["PerIncomingRequestLogBuffering:Rules:0:LogLevel"] = "Warning", + ["PerIncomingRequestLogBuffering:Rules:1:CategoryName"] = "Category2", + ["PerIncomingRequestLogBuffering:Rules:1:LogLevel"] = "Error" + }; + + IConfigurationRoot configuration = new ConfigurationBuilder() + .AddInMemoryCollection(configValues) + .Build(); + + var options = new PerRequestLogBufferingOptions(); + var configureOptions = new PerRequestLogBufferingConfigureOptions(configuration); + + // Act + configureOptions.Configure(options); + + // Assert + Assert.Equal(2, options.Rules.Count); + Assert.Equal("Category1", options.Rules[0].CategoryName); + Assert.Equal(LogLevel.Warning, options.Rules[0].LogLevel); + Assert.Equal("Category2", options.Rules[1].CategoryName); + Assert.Equal(LogLevel.Error, options.Rules[1].LogLevel); + } +} +#endif diff --git a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingOptionsCustomValidatorTests.cs b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingOptionsCustomValidatorTests.cs new file mode 100644 index 00000000000..9e9710a21c3 --- /dev/null +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/PerRequestLogBufferingOptionsCustomValidatorTests.cs @@ -0,0 +1,31 @@ +// 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.Collections.Generic; +using Microsoft.Extensions.Diagnostics.Buffering; +using Xunit; + +namespace Microsoft.AspNetCore.Diagnostics.Buffering.Test; + +public class PerRequestLogBufferingOptionsCustomValidatorTests +{ + [Fact] + public void GivenInvalidCategory_Fails() + { + var validator = new PerRequestLogBufferingOptionsCustomValidator(); + var options = new PerRequestLogBufferingOptions + { + Rules = new List + { + new LogBufferingFilterRule(categoryName: "**") + }, + }; + + var validationResult = validator.Validate(string.Empty, options); + + Assert.True(validationResult.Failed, validationResult.FailureMessage); + Assert.Contains(nameof(options.Rules), validationResult.FailureMessage); + } +} +#endif diff --git a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/AcceptanceTests.cs b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/AcceptanceTests.cs index 01a962f2f90..d94800adbc5 100644 --- a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/AcceptanceTests.cs +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/AcceptanceTests.cs @@ -28,6 +28,12 @@ using Microsoft.Net.Http.Headers; using Microsoft.Shared.Text; using Xunit; +#if NET9_0_OR_GREATER +using System.Collections.Generic; +using System.Linq; +using System.Threading; +using Microsoft.Extensions.Diagnostics.Buffering; +#endif namespace Microsoft.AspNetCore.Diagnostics.Logging.Test; @@ -54,7 +60,45 @@ public static void Configure(IApplicationBuilder app) { app.UseRouting(); app.UseHttpLogging(); +#if NET9_0_OR_GREATER + app.Map("/logatrequest", static x => + x.Run(static async context => + { + await context.Request.Body.DrainAsync(CancellationToken.None); + + // normally, this would be a Middleware and HttpRequestLogBuffer would be injected via constructor + ILoggerFactory loggerFactory = context.RequestServices.GetRequiredService(); + ILogger logger = loggerFactory.CreateLogger("logatrequest"); + + logger.LogInformation("Log Information from Request"); + + var hugeState = new List> + { + new("test", Enumerable.Repeat("test", 10000).ToArray()) + }; + logger.LogTrace($"Log Trace from Request, {hugeState}"); + })); + + app.Map("/flushrequestlogs", static x => + x.Run(static async context => + { + await context.Request.Body.DrainAsync(CancellationToken.None); + // normally, this would be a Middleware and HttpRequestLogBuffer would be injected via constructor + var bufferManager = context.RequestServices.GetService(); + bufferManager?.Flush(); + })); + + app.Map("/flushalllogs", static x => + x.Run(static async context => + { + await context.Request.Body.DrainAsync(CancellationToken.None); + + // normally, this would be a Middleware and HttpRequestLogBuffer would be injected via constructor + var bufferManager = context.RequestServices.GetService(); + bufferManager?.Flush(); + })); +#endif app.Map("/error", static x => x.Run(static async context => { @@ -755,7 +799,160 @@ await RunAsync( } }); } +#if NET9_0_OR_GREATER + [Fact] + public async Task HttpRequestBuffering() + { + await RunAsync( + LogLevel.Trace, + services => services + .AddLogging(builder => + { + // enable Microsoft.AspNetCore.Routing.Matching.DfaMatcher debug logs + // which are produced by ASP.NET Core within HTTP context. + // This is what is going to be buffered and tested. + builder.AddFilter("Microsoft.AspNetCore.Routing.Matching.DfaMatcher", LogLevel.Debug); + + // Disable logs from HTTP logging middleware, otherwise even though they are not buffered, + // they will be logged as usual and contaminate test results: + builder.AddFilter("Microsoft.AspNetCore.HttpLogging", LogLevel.None); + + builder.AddPerIncomingRequestBuffer(LogLevel.Debug); + }), + async (logCollector, client, sp) => + { + // just HTTP request logs: + using HttpResponseMessage response = await client.GetAsync("/flushrequestlogs").ConfigureAwait(false); + Assert.True(response.IsSuccessStatusCode); + await WaitForLogRecordsAsync(logCollector, _defaultLogTimeout); + Assert.Equal(1, logCollector.Count); + Assert.Equal(LogLevel.Debug, logCollector.LatestRecord.Level); + Assert.Equal("Microsoft.AspNetCore.Routing.Matching.DfaMatcher", logCollector.LatestRecord.Category); + + // HTTP request logs + global logs: + using var loggerFactory = sp.GetRequiredService(); + ILogger logger = loggerFactory.CreateLogger("test"); + logger.LogTrace("This is a log message"); + using HttpResponseMessage response2 = await client.GetAsync("/flushalllogs").ConfigureAwait(false); + Assert.True(response2.IsSuccessStatusCode); + await WaitForLogRecordsAsync(logCollector, _defaultLogTimeout); + + // 1st and 2nd log records are from DfaMatcher, and 3rd is from our test category + Assert.Equal(3, logCollector.Count); + Assert.Equal(LogLevel.Trace, logCollector.LatestRecord.Level); + Assert.Equal("test", logCollector.LatestRecord.Category); + }); + } + + [Fact] + public async Task HttpRequestBuffering_RespectsAutoFlush() + { + await RunAsync( + LogLevel.Trace, + services => services + .AddLogging(builder => + { + // enable Microsoft.AspNetCore.Routing.Matching.DfaMatcher debug logs + // which are produced by ASP.NET Core within HTTP context. + // This is what is going to be buffered and tested. + builder.AddFilter("Microsoft.AspNetCore.Routing.Matching.DfaMatcher", LogLevel.Debug); + // Disable logs from HTTP logging middleware, otherwise even though they are not buffered, + // they will be logged as usual and contaminate test results: + builder.AddFilter("Microsoft.AspNetCore.HttpLogging", LogLevel.None); + + builder.AddPerIncomingRequestBuffer(options => + { + options.AutoFlushDuration = TimeSpan.FromMinutes(30); + options.Rules.Add(new LogBufferingFilterRule(logLevel: LogLevel.Debug)); + }); + + builder.Services.Configure(options => + { + options.AutoFlushDuration = TimeSpan.FromMinutes(30); + }); + }), + async (logCollector, client, sp) => + { + using var loggerFactory = sp.GetRequiredService(); + ILogger logger = loggerFactory.CreateLogger("test"); + logger.LogTrace("This is a log message"); + using HttpResponseMessage response2 = await client.GetAsync("/flushalllogs").ConfigureAwait(false); + + // log again, but since AutoFlushDuration is long enough, the log won't be buffered, + // so we don't need to flush() again and expect it to be emitted anyway. + logger.LogTrace("This is a log message 2"); + await WaitForLogRecordsAsync(logCollector, _defaultLogTimeout); + + // 1st log record is from DfaMatcher, + // and 2nd 3rd are from our "test" category + Assert.Equal(3, logCollector.Count); + Assert.Equal(LogLevel.Trace, logCollector.LatestRecord.Level); + Assert.Equal("test", logCollector.LatestRecord.Category); + }); + } + + [Fact] + public async Task HttpRequestBuffering_DoesNotBufferDisabledOrOversizedLogs() + { + await RunAsync( + LogLevel.Trace, + services => services + .AddLogging(builder => + { + // enable Microsoft.AspNetCore.Routing.Matching.DfaMatcher debug logs + // which are produced by ASP.NET Core within HTTP context. + // This is what is going to be buffered and tested. + builder.AddFilter("Microsoft.AspNetCore.Routing.Matching.DfaMatcher", LogLevel.Debug); + + // Disable logs from HTTP logging middleware, otherwise even though they are not buffered, + // they will be logged as usual and contaminate test results: + builder.AddFilter("Microsoft.AspNetCore.HttpLogging", LogLevel.None); + + builder.AddPerIncomingRequestBuffer(options => + { + options.AutoFlushDuration = TimeSpan.Zero; + options.MaxLogRecordSizeInBytes = 500; + options.Rules.Add(new LogBufferingFilterRule(logLevel: LogLevel.Debug)); + options.Rules.Add(new LogBufferingFilterRule(logLevel: LogLevel.Debug, categoryName: "logatrequest")); + }); + + builder.Services.Configure(options => + { + options.AutoFlushDuration = TimeSpan.Zero; + options.MaxLogRecordSizeInBytes = 500; + }); + }), + async (logCollector, client, sp) => + { + using var loggerFactory = sp.GetRequiredService(); + ILogger logger = loggerFactory.CreateLogger("test"); + logger.LogTrace("This is a log message"); + using HttpResponseMessage response2 = await client.GetAsync("/flushalllogs").ConfigureAwait(false); + using HttpResponseMessage response3 = await client.GetAsync("/logatrequest").ConfigureAwait(false); + + // log again, Information log buffering is not enabled, + // so we don't need to flush() again and expect it to be emitted anyway. + logger.LogInformation("This is a log message 2"); + + // log again, but this log size is too big to be buffered, + // so we don't need to flush() again and expect it to be emitted anyway. + var hugeState = new List> + { + new("test", Enumerable.Repeat("test", 10000).ToArray()) + }; + logger.LogTrace($"This is a huge log message 3, {hugeState}"); + await WaitForLogRecordsAsync(logCollector, _defaultLogTimeout); + + // 1st log record is from DfaMatcher, + // 2, 3, 4th are from our "test" category + // and 5 and 6th are logs from the /logatrequest endpoint + Assert.Equal(6, logCollector.Count); + Assert.Equal(LogLevel.Trace, logCollector.LatestRecord.Level); + Assert.Equal("test", logCollector.LatestRecord.Category); + }); + } +#endif [Fact] public async Task HttpLogging_LogRecordIsNotCreated_If_Disabled() { diff --git a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/HeaderNormalizerTests.cs b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/HeaderNormalizerTests.cs index 481a186a08d..82a063cc55c 100644 --- a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/HeaderNormalizerTests.cs +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/HeaderNormalizerTests.cs @@ -5,6 +5,8 @@ using Microsoft.Extensions.Compliance.Classification; using Xunit; +namespace Microsoft.AspNetCore.Diagnostics.Logging.Test; + public class HeaderNormalizerTests { [Fact] diff --git a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/appsettings.json b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/appsettings.json index c1503ee98da..6a6e0bc9e25 100644 --- a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/appsettings.json +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/appsettings.json @@ -17,5 +17,18 @@ "userId": "EUII", "userContent": "CustomerContent" } + }, + "PerIncomingRequestLogBuffering": { + "Rules": [ + { + "CategoryName": "Program.MyLogger", + "LogLevel": "Information", + "EventId": 1, + "EventName": "number one" + }, + { + "LogLevel": "Information" + } + ] } } diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferLoggerBuilderExtensionsTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferLoggerBuilderExtensionsTests.cs new file mode 100644 index 00000000000..a267c708f50 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferLoggerBuilderExtensionsTests.cs @@ -0,0 +1,72 @@ +// 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.Generic; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Xunit; + +namespace Microsoft.Extensions.Diagnostics.Buffering.Test; + +public class GlobalBufferLoggerBuilderExtensionsTests +{ + [Fact] + public void WithLogLevel_RegistersInDI() + { + var serviceCollection = new ServiceCollection(); + serviceCollection.AddLogging(builder => + { + builder.AddGlobalBuffer(LogLevel.Warning); + }); + + ServiceProvider serviceProvider = serviceCollection.BuildServiceProvider(); + var bufferManager = serviceProvider.GetService(); + + Assert.NotNull(bufferManager); + Assert.IsAssignableFrom(bufferManager); + } + + [Fact] + public void WhenArgumentNull_Throws() + { + ILoggingBuilder? builder = null; + IConfiguration? configuration = null; + + Assert.Throws(() => builder!.AddGlobalBuffer(LogLevel.Warning)); + Assert.Throws(() => builder!.AddGlobalBuffer(configuration!)); + } + + [Fact] + public void WithConfiguration_RegistersInDI() + { + List expectedData = + [ + new ("Program.MyLogger", LogLevel.Information, 1, "number one", [new("region", "westus2"), new ("priority", 1)]), + new (logLevel: LogLevel.Information), + ]; + ConfigurationBuilder configBuilder = new ConfigurationBuilder(); + configBuilder.AddJsonFile("appsettings.json"); + IConfigurationRoot configuration = configBuilder.Build(); + var serviceCollection = new ServiceCollection(); + serviceCollection.AddLogging(builder => + { + builder.AddGlobalBuffer(configuration); + builder.Services.Configure(options => + { + options.MaxLogRecordSizeInBytes = 33; + }); + }); + ServiceProvider serviceProvider = serviceCollection.BuildServiceProvider(); + var options = serviceProvider.GetService>(); + Assert.NotNull(options); + Assert.NotNull(options.CurrentValue); + Assert.Equal(33, options.CurrentValue.MaxLogRecordSizeInBytes); // value comes from the Configure() call + Assert.Equal(1000, options.CurrentValue.MaxBufferSizeInBytes); // value comes from appsettings.json + Assert.Equal(TimeSpan.FromSeconds(30), options.CurrentValue.AutoFlushDuration); // value comes from default + Assert.Equivalent(expectedData, options.CurrentValue.Rules); + } +} +#endif diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalLogBufferingConfigureOptionsTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalLogBufferingConfigureOptionsTests.cs new file mode 100644 index 00000000000..8f99ef12183 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalLogBufferingConfigureOptionsTests.cs @@ -0,0 +1,126 @@ +// 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.Collections.Generic; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace Microsoft.Extensions.Diagnostics.Buffering.Test; + +public class GlobalLogBufferingConfigureOptionsTests +{ + [Fact] + public void Configure_WhenConfigurationIsNull_DoesNotModifyOptions() + { + // Arrange + var options = new GlobalLogBufferingOptions(); + var configureOptions = new GlobalLogBufferingConfigureOptions(null!); + + // Act + configureOptions.Configure(options); + + // Assert + Assert.Equivalent(new GlobalLogBufferingOptions(), options); + } + + [Fact] + public void Configure_WhenSectionDoesNotExist_DoesNotModifyOptions() + { + // Arrange + var options = new GlobalLogBufferingOptions(); + var configuration = new ConfigurationBuilder().Build(); + var configureOptions = new GlobalLogBufferingConfigureOptions(configuration); + + // Act + configureOptions.Configure(options); + + // Assert + Assert.Equivalent(new GlobalLogBufferingOptions(), options); + } + + [Fact] + public void Configure_WhenSectionContainsInvalidPropertyNames_DoesNotModifyOptions() + { + // Arrange + var configValues = new Dictionary + { + ["GlobalLogBuffering"] = "1", + }; + + var configuration = new ConfigurationBuilder() + .AddInMemoryCollection(configValues) + .Build(); + + var options = new GlobalLogBufferingOptions(); + var configureOptions = new GlobalLogBufferingConfigureOptions(configuration); + + // Act + configureOptions.Configure(options); + + // Assert + Assert.Equivalent(new GlobalLogBufferingOptions(), options); + } + + [Fact] + public void Configure_WithValidConfiguration_UpdatesOptions() + { + // Arrange + var configValues = new Dictionary + { + ["GlobalLogBuffering:MaxLogRecordSizeInBytes"] = "1024", + ["GlobalLogBuffering:MaxBufferSizeInBytes"] = "4096", + ["GlobalLogBuffering:Rules:0:CategoryName"] = "TestCategory", + ["GlobalLogBuffering:Rules:0:LogLevel"] = "Information" + }; + + var configuration = new ConfigurationBuilder() + .AddInMemoryCollection(configValues) + .Build(); + + var options = new GlobalLogBufferingOptions(); + var configureOptions = new GlobalLogBufferingConfigureOptions(configuration); + + // Act + configureOptions.Configure(options); + + // Assert + Assert.Equal(1024, options.MaxLogRecordSizeInBytes); + Assert.Equal(4096, options.MaxBufferSizeInBytes); + Assert.Single(options.Rules); + Assert.Equal("TestCategory", options.Rules[0].CategoryName); + Assert.Equal(LogLevel.Information, options.Rules[0].LogLevel); + } + + [Fact] + public void Configure_WithMultipleRules_AddsAllRules() + { + // Arrange + var configValues = new Dictionary + { + ["GlobalLogBuffering:Rules:0:CategoryName"] = "Category1", + ["GlobalLogBuffering:Rules:0:LogLevel"] = "Warning", + ["GlobalLogBuffering:Rules:1:CategoryName"] = "Category2", + ["GlobalLogBuffering:Rules:1:LogLevel"] = "Error" + }; + + var configuration = new ConfigurationBuilder() + .AddInMemoryCollection(configValues) + .Build(); + + var options = new GlobalLogBufferingOptions(); + var configureOptions = new GlobalLogBufferingConfigureOptions(configuration); + + // Act + configureOptions.Configure(options); + + // Assert + Assert.Equal(2, options.Rules.Count); + Assert.Equal("Category1", options.Rules[0].CategoryName); + Assert.Equal(LogLevel.Warning, options.Rules[0].LogLevel); + Assert.Equal("Category2", options.Rules[1].CategoryName); + Assert.Equal(LogLevel.Error, options.Rules[1].LogLevel); + } +} +#endif diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalLogBufferingOptionsCustomValidatorTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalLogBufferingOptionsCustomValidatorTests.cs new file mode 100644 index 00000000000..7c77804eb06 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalLogBufferingOptionsCustomValidatorTests.cs @@ -0,0 +1,30 @@ +// 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.Collections.Generic; +using Xunit; + +namespace Microsoft.Extensions.Diagnostics.Buffering.Test; + +public class GlobalLogBufferingOptionsCustomValidatorTests +{ + [Fact] + public void GivenInvalidCategory_Fails() + { + var validator = new GlobalLogBufferingOptionsCustomValidator(); + var options = new GlobalLogBufferingOptions + { + Rules = new List + { + new LogBufferingFilterRule(categoryName: "**") + }, + }; + + var validationResult = validator.Validate(string.Empty, options); + + Assert.True(validationResult.Failed, validationResult.FailureMessage); + Assert.Contains(nameof(options.Rules), validationResult.FailureMessage); + } +} +#endif diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/LogBufferingFilterRuleTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/LogBufferingFilterRuleTests.cs new file mode 100644 index 00000000000..222d2aacc9a --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/LogBufferingFilterRuleTests.cs @@ -0,0 +1,99 @@ +// 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.Collections.Generic; +using System.Linq; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace Microsoft.Extensions.Diagnostics.Buffering.Test; +public class LogBufferingFilterRuleTests +{ + private readonly LogBufferingFilterRuleSelector _selector = new(); + + [Fact] + public void SelectsRightRule() + { + // Arrange + var rules = new List + { + new LogBufferingFilterRule(), + new LogBufferingFilterRule(eventId: 1), + new LogBufferingFilterRule(logLevel: LogLevel.Information, eventId: 1), + new LogBufferingFilterRule(logLevel: LogLevel.Information, eventId: 1), + new LogBufferingFilterRule(logLevel: LogLevel.Warning), + new LogBufferingFilterRule(logLevel: LogLevel.Warning, eventId: 2), + new LogBufferingFilterRule(logLevel: LogLevel.Warning, eventId: 1), + new LogBufferingFilterRule("Program1.MyLogger", LogLevel.Warning, 1), + new LogBufferingFilterRule("Program.*MyLogger1", LogLevel.Warning, 1), + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning, 1, attributes: [new("region2", "westus2")]), // inapplicable key + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning, 1, attributes:[new("region", "westus3")]), // inapplicable value + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning, 1, attributes:[new("region", "westus2")]), // the best rule - [11] + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning, 2), + new LogBufferingFilterRule("Program.MyLogger", eventId: 1), + new LogBufferingFilterRule(logLevel: LogLevel.Warning, eventId: 1), + new LogBufferingFilterRule("Program", LogLevel.Warning, 1), + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning), + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Error, 1), + }; + + // Act + LogBufferingFilterRule[] categorySpecificRules = LogBufferingFilterRuleSelector.SelectByCategory(rules, "Program.MyLogger"); + LogBufferingFilterRule? result = _selector.Select( + categorySpecificRules, + LogLevel.Warning, + 1, + [new("region", "westus2")]); + + // Assert + Assert.Same(rules[11], result); + } + + [Fact] + public void WhenManyRuleApply_SelectsLast() + { + // Arrange + var rules = new List + { + new LogBufferingFilterRule(logLevel: LogLevel.Information, eventId: 1), + new LogBufferingFilterRule(logLevel: LogLevel.Information, eventId: 1), + new LogBufferingFilterRule(logLevel: LogLevel.Warning), + new LogBufferingFilterRule(logLevel: LogLevel.Warning, eventId: 2), + new LogBufferingFilterRule(logLevel: LogLevel.Warning, eventId: 1), + new LogBufferingFilterRule("Program1.MyLogger", LogLevel.Warning, 1), + new LogBufferingFilterRule("Program.*MyLogger1", LogLevel.Warning, 1), + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning, 1), + new LogBufferingFilterRule("Program.MyLogger*", LogLevel.Warning, 1), + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning, 1, attributes:[new("region", "westus2")]), // the best rule + new LogBufferingFilterRule("Program.MyLogger*", LogLevel.Warning, 1, attributes:[new("region", "westus2")]), // same as the best, but last and should be selected + }; + + // Act + LogBufferingFilterRule[] categorySpecificRules = LogBufferingFilterRuleSelector.SelectByCategory(rules, "Program.MyLogger"); + LogBufferingFilterRule? result = _selector.Select(categorySpecificRules, LogLevel.Warning, 1, [new("region", "westus2")]); + + // Assert + Assert.Same(rules.Last(), result); + } + + [Fact] + public void CanWorkWithValueTypeAttributes() + { + // Arrange + var rules = new List + { + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning, 1, attributes:[new("priority", 1)]), + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning, 1, attributes:[new("priority", 2)]), // the best rule + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning, 1, attributes:[new("priority", 3)]), + new LogBufferingFilterRule("Program.MyLogger", LogLevel.Warning, 1), + }; + + // Act + LogBufferingFilterRule[] categorySpecificRules = LogBufferingFilterRuleSelector.SelectByCategory(rules, "Program.MyLogger"); + LogBufferingFilterRule? result = _selector.Select(categorySpecificRules, LogLevel.Warning, 1, [new("priority", "2")]); + + // Assert + Assert.Same(rules[1], result); + } +} +#endif diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs index 9ff23e11859..b31aabb0083 100644 --- a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs @@ -12,6 +12,10 @@ using Microsoft.Extensions.Options; using Moq; using Xunit; +#if NET9_0_OR_GREATER +using System.Threading.Tasks; +using Microsoft.Extensions.Diagnostics.Buffering; +#endif namespace Microsoft.Extensions.Logging.Test; @@ -915,6 +919,112 @@ public static void LegacyLogging_OriginalFormatMustBeLastInTheListOfStatePropert Assert.Equal("V4", property.Value); } +#if NET9_0_OR_GREATER + [Fact] + public static void GlobalBuffering_CanonicalUsecase() + { + using var provider = new Provider(); + using ILoggerFactory factory = Utils.CreateLoggerFactory( + builder => + { + builder.AddProvider(provider); + builder.AddGlobalBuffer(LogLevel.Warning); + }); + + ILogger logger = factory.CreateLogger("my category"); + logger.LogWarning("MSG0"); + logger.Log(LogLevel.Warning, new EventId(2, "ID2"), "some state", null, (_, _) => "MSG2"); + + // nothing is logged because the buffer not flushed yet + Assert.Equal(0, provider.Logger!.Collector.Count); + + // instead of this, users would get LogBuffer from DI and call Flush on it + Utils.DisposingLoggerFactory dlf = (Utils.DisposingLoggerFactory)factory; + GlobalLogBuffer buffer = dlf.ServiceProvider.GetRequiredService(); + + buffer.Flush(); + + // 2 log records emitted because the buffer has been flushed + Assert.Equal(2, provider.Logger!.Collector.Count); + } + + [Fact] + public static void GlobalBuffering_ParallelLogging() + { + using var provider = new Provider(); + using ILoggerFactory factory = Utils.CreateLoggerFactory( + builder => + { + builder.AddProvider(provider); + builder.AddGlobalBuffer(LogLevel.Warning); + }); + + ILogger logger = factory.CreateLogger("my category"); + + // 1000 threads logging at the same time + Parallel.For(0, 1000, _ => + { + logger.LogWarning("MSG0"); + logger.Log(LogLevel.Warning, new EventId(2, "ID2"), "some state", null, (_, _) => "MSG2"); + }); + + // nothing is logged because the buffer not flushed yet + Assert.Equal(0, provider.Logger!.Collector.Count); + + Utils.DisposingLoggerFactory dlf = (Utils.DisposingLoggerFactory)factory; + GlobalLogBuffer buffer = dlf.ServiceProvider.GetRequiredService(); + + buffer.Flush(); + + // 2000 log records emitted because the buffer has been flushed + Assert.Equal(2000, provider.Logger!.Collector.Count); + } + + [Fact] + public static async Task GlobalBuffering_ParallelLoggingAndFlushing() + { + // Arrange + using var provider = new Provider(); + using ILoggerFactory factory = Utils.CreateLoggerFactory( + builder => + { + builder.AddProvider(provider); + builder.AddGlobalBuffer(options => + { + options.AutoFlushDuration = TimeSpan.Zero; + options.Rules.Add(new LogBufferingFilterRule(logLevel: LogLevel.Warning)); + }); + }); + + ILogger logger = factory.CreateLogger("my category"); + Utils.DisposingLoggerFactory dlf = (Utils.DisposingLoggerFactory)factory; + GlobalLogBuffer buffer = dlf.ServiceProvider.GetRequiredService(); + + // Act - Run logging and flushing operations in parallel + await Task.Run(() => + { + Parallel.For(0, 100, i => + { + logger.LogWarning("MSG0"); + logger.LogWarning("MSG1"); + logger.LogWarning("MSG2"); + logger.LogWarning("MSG3"); + logger.LogWarning("MSG4"); + logger.LogWarning("MSG5"); + logger.LogWarning("MSG6"); + logger.LogWarning("MSG7"); + logger.LogWarning("MSG8"); + logger.LogWarning("MSG9"); + buffer.Flush(); + }); + }); + + buffer.Flush(); + Assert.Equal(1000, provider.Logger!.Collector.Count); + } + +#endif + private sealed class CustomLoggerProvider : ILoggerProvider { private readonly string _providerName; diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/Utils.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/Utils.cs index bf09f8cb91c..99ec499fb47 100644 --- a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/Utils.cs +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/Utils.cs @@ -3,7 +3,6 @@ using System; using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.Logging; namespace Microsoft.Extensions.Logging.Test; @@ -24,21 +23,21 @@ public static ILoggerFactory CreateLoggerFactory(Action? config return new DisposingLoggerFactory(loggerFactory, serviceProvider); } - private sealed class DisposingLoggerFactory : ILoggerFactory + internal sealed class DisposingLoggerFactory : ILoggerFactory { private readonly ILoggerFactory _loggerFactory; - private readonly ServiceProvider _serviceProvider; + internal ServiceProvider ServiceProvider { get; } public DisposingLoggerFactory(ILoggerFactory loggerFactory, ServiceProvider serviceProvider) { _loggerFactory = loggerFactory; - _serviceProvider = serviceProvider; + ServiceProvider = serviceProvider; } public void Dispose() { - _serviceProvider.Dispose(); + ServiceProvider.Dispose(); } public ILogger CreateLogger(string categoryName) diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/appsettings.json b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/appsettings.json index 3eb6e04e7fa..2bfec375f61 100644 --- a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/appsettings.json +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/appsettings.json @@ -35,5 +35,30 @@ "Probability": 0.1 } ] + }, + "GlobalLogBuffering": { + "MaxLogRecordSizeInBytes": 100, + "MaxBufferSizeInBytes": 1000, + "Rules": [ + { + "CategoryName": "Program.MyLogger", + "LogLevel": "Information", + "EventId": 1, + "EventName" : "number one", + "Attributes": [ + { + "key": "region", + "value": "westus2" + }, + { + "key": "priority", + "value": 1 + } + ] + }, + { + "LogLevel": "Information" + } + ] } } diff --git a/test/Shared/Throw/DoubleTests.cs b/test/Shared/Throw/DoubleTests.cs index 517ce68af90..72e33cfaf78 100644 --- a/test/Shared/Throw/DoubleTests.cs +++ b/test/Shared/Throw/DoubleTests.cs @@ -53,13 +53,14 @@ public void IfDoubleGreaterThan_DoesntThrow_WhenEqual() [Fact] public void IfDoubleLessThanOrEqual_ThrowWhenEqual() { - var exception = Assert.Throws(() => Throw.IfLessThanOrEqual(1.2, 1.2, "paramName")); + const double TestValue = 1.2; + var exception = Assert.Throws(() => Throw.IfLessThanOrEqual(TestValue, TestValue, "paramName")); Assert.Equal("paramName", exception.ParamName); - Assert.StartsWith("Argument less or equal than minimum value 1.2", exception.Message); + Assert.StartsWith($"Argument less or equal than minimum value {TestValue}", exception.Message); - exception = Assert.Throws(() => Throw.IfLessThanOrEqual(double.NaN, 1.2, "paramName")); + exception = Assert.Throws(() => Throw.IfLessThanOrEqual(double.NaN, TestValue, "paramName")); Assert.Equal("paramName", exception.ParamName); - Assert.StartsWith("Argument less or equal than minimum value 1.2", exception.Message); + Assert.StartsWith($"Argument less or equal than minimum value {TestValue}", exception.Message); } [Fact] @@ -72,13 +73,14 @@ public void IfDoubleLessThanOrEqual_DoesntThrow_WhenGreaterThan() [Fact] public void IfDoubleGreaterThanOrEqual_ThrowWhenEqual() { - var exception = Assert.Throws(() => Throw.IfGreaterThanOrEqual(1.22, 1.22, "paramName")); + const double TestValue = 1.22; + var exception = Assert.Throws(() => Throw.IfGreaterThanOrEqual(TestValue, TestValue, "paramName")); Assert.Equal("paramName", exception.ParamName); - Assert.StartsWith("Argument greater or equal than maximum value 1.22", exception.Message); + Assert.StartsWith($"Argument greater or equal than maximum value {TestValue}", exception.Message); - exception = Assert.Throws(() => Throw.IfGreaterThanOrEqual(double.NaN, 1.22, "paramName")); + exception = Assert.Throws(() => Throw.IfGreaterThanOrEqual(double.NaN, TestValue, "paramName")); Assert.Equal("paramName", exception.ParamName); - Assert.StartsWith("Argument greater or equal than maximum value 1.22", exception.Message); + Assert.StartsWith($"Argument greater or equal than maximum value {TestValue}", exception.Message); } [Fact]