diff --git a/eng/MSBuild/Shared.props b/eng/MSBuild/Shared.props index a68b0e4298f..599fc2bde44 100644 --- a/eng/MSBuild/Shared.props +++ b/eng/MSBuild/Shared.props @@ -42,4 +42,8 @@ + + + + diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBuffer.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBuffer.cs index 1d25077f8f0..64591cd910b 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBuffer.cs +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBuffer.cs @@ -4,94 +4,111 @@ #if NET9_0_OR_GREATER using System; using System.Collections.Concurrent; -using System.Collections.Generic; +using System.Diagnostics.CodeAnalysis; using Microsoft.Extensions.Diagnostics; using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Options; +using Microsoft.Shared.Diagnostics; +using static Microsoft.Extensions.Logging.ExtendedLogger; namespace Microsoft.AspNetCore.Diagnostics.Logging; internal sealed class HttpRequestBuffer : ILoggingBuffer { private readonly IOptionsMonitor _options; - private readonly ConcurrentDictionary> _buffers; + private readonly IOptionsMonitor _globalOptions; + private readonly ConcurrentQueue _buffer; private readonly TimeProvider _timeProvider = TimeProvider.System; + private readonly IBufferSink _bufferSink; + private readonly object _bufferCapacityLocker = new(); + private DateTimeOffset _truncateAfter; private DateTimeOffset _lastFlushTimestamp; - public HttpRequestBuffer(IOptionsMonitor options) + public HttpRequestBuffer(IBufferSink bufferSink, + IOptionsMonitor options, + IOptionsMonitor globalOptions) { _options = options; - _buffers = new ConcurrentDictionary>(); - _lastFlushTimestamp = _timeProvider.GetUtcNow(); - } + _globalOptions = globalOptions; + _bufferSink = bufferSink; + _buffer = new ConcurrentQueue(); - internal HttpRequestBuffer(IOptionsMonitor options, TimeProvider timeProvider) - : this(options) - { - _timeProvider = timeProvider; - _lastFlushTimestamp = _timeProvider.GetUtcNow(); + _truncateAfter = _timeProvider.GetUtcNow(); } - public bool TryEnqueue( - IBufferedLogger logger, + [RequiresUnreferencedCode( + "Calls Microsoft.Extensions.Logging.SerializedLogRecord.SerializedLogRecord(LogLevel, EventId, DateTimeOffset, IReadOnlyList>, Exception, String)")] + public bool TryEnqueue( LogLevel logLevel, string category, EventId eventId, - IReadOnlyList> joiner, + TState attributes, Exception? exception, - string formatter) + Func formatter) { if (!IsEnabled(category, logLevel, eventId)) { return false; } - var record = new HttpRequestBufferedLogRecord(logLevel, eventId, joiner, exception, formatter); - var queue = _buffers.GetOrAdd(logger, _ => new ConcurrentQueue()); - - // probably don't need to limit buffer capacity? - // because buffer is disposed when the respective HttpContext is disposed - // don't expect it to grow so much to cause a problem? - if (queue.Count >= _options.CurrentValue.PerRequestCapacity) + switch (attributes) { - _ = queue.TryDequeue(out HttpRequestBufferedLogRecord? _); + case ModernTagJoiner modernTagJoiner: + _buffer.Enqueue(new SerializedLogRecord(logLevel, eventId, _timeProvider.GetUtcNow(), modernTagJoiner, exception, + ((Func)(object)formatter)(modernTagJoiner, exception))); + break; + case LegacyTagJoiner legacyTagJoiner: + _buffer.Enqueue(new SerializedLogRecord(logLevel, eventId, _timeProvider.GetUtcNow(), legacyTagJoiner, exception, + ((Func)(object)formatter)(legacyTagJoiner, exception))); + break; + default: + Throw.ArgumentException(nameof(attributes), $"Unsupported type of the log attributes object detected: {typeof(TState)}"); + break; } - queue.Enqueue(record); + var now = _timeProvider.GetUtcNow(); + lock (_bufferCapacityLocker) + { + if (now >= _truncateAfter) + { + _truncateAfter = now.Add(_options.CurrentValue.PerRequestDuration); + TruncateOverlimit(); + } + } return true; } + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.BufferSink.LogRecords(IEnumerable)")] public void Flush() { - foreach (var (logger, queue) in _buffers) - { - var result = new List(); - while (!queue.IsEmpty) - { - if (queue.TryDequeue(out HttpRequestBufferedLogRecord? item)) - { - result.Add(item); - } - } - - logger.LogRecords(result); - } + var result = _buffer.ToArray(); + _buffer.Clear(); _lastFlushTimestamp = _timeProvider.GetUtcNow(); + + _bufferSink.LogRecords(result); } public bool IsEnabled(string category, LogLevel logLevel, EventId eventId) { - if (_timeProvider.GetUtcNow() < _lastFlushTimestamp + _options.CurrentValue.SuspendAfterFlushDuration) + if (_timeProvider.GetUtcNow() < _lastFlushTimestamp + _globalOptions.CurrentValue.SuspendAfterFlushDuration) { return false; } - LoggerFilterRuleSelector.Select(_options.CurrentValue.Rules, category, logLevel, eventId, out BufferFilterRule? rule); + LoggerFilterRuleSelector.Select(_options.CurrentValue.Rules, category, logLevel, eventId, out BufferFilterRule? rule); return rule is not null; } + + public void TruncateOverlimit() + { + // Capacity is a soft limit, which might be exceeded, esp. in multi-threaded environments. + while (_buffer.Count > _options.CurrentValue.PerRequestCapacity) + { + _ = _buffer.TryDequeue(out _); + } + } } #endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferLoggerBuilderExtensions.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferLoggerBuilderExtensions.cs index 50faa1522e0..b3c4f94f786 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferLoggerBuilderExtensions.cs +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferLoggerBuilderExtensions.cs @@ -9,6 +9,7 @@ using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; +using Microsoft.Extensions.Diagnostics.Buffering; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; using Microsoft.Shared.DiagnosticIds; @@ -30,14 +31,16 @@ public static class HttpRequestBufferLoggerBuilderExtensions /// The to add. /// The value of . /// is . - public static ILoggingBuilder AddHttpRequestBuffer(this ILoggingBuilder builder, IConfiguration configuration) + public static ILoggingBuilder AddHttpRequestBuffering(this ILoggingBuilder builder, IConfiguration configuration) { _ = Throw.IfNull(builder); _ = Throw.IfNull(configuration); return builder .AddHttpRequestBufferConfiguration(configuration) - .AddHttpRequestBufferProvider(); + .AddHttpRequestBufferManager() + .AddGlobalBufferConfiguration(configuration) + .AddGlobalBufferManager(); } /// @@ -49,7 +52,7 @@ public static ILoggingBuilder AddHttpRequestBuffer(this ILoggingBuilder builder, /// The buffer configuration options. /// The value of . /// is . - public static ILoggingBuilder AddHttpRequestBuffer(this ILoggingBuilder builder, LogLevel? level = null, Action? configure = null) + public static ILoggingBuilder AddHttpRequestBuffering(this ILoggingBuilder builder, LogLevel? level = null, Action? configure = null) { _ = Throw.IfNull(builder); @@ -57,7 +60,10 @@ public static ILoggingBuilder AddHttpRequestBuffer(this ILoggingBuilder builder, .Configure(options => options.Rules.Add(new BufferFilterRule(null, level, null))) .Configure(configure ?? new Action(_ => { })); - return builder.AddHttpRequestBufferProvider(); + return builder + .AddHttpRequestBufferManager() + .AddGlobalBuffer(level) + .AddGlobalBufferManager(); } /// @@ -66,16 +72,20 @@ public static ILoggingBuilder AddHttpRequestBuffer(this ILoggingBuilder builder, /// The . /// The so that additional calls can be chained. /// is . - public static ILoggingBuilder AddHttpRequestBufferProvider(this ILoggingBuilder builder) + internal static ILoggingBuilder AddHttpRequestBufferManager(this ILoggingBuilder builder) { _ = Throw.IfNull(builder); - builder.Services.TryAddScoped(); - builder.Services.TryAddScoped(sp => sp.GetRequiredService()); builder.Services.TryAddSingleton(); - builder.Services.TryAddActivatedSingleton(); - return builder.AddGlobalBufferProvider(); + builder.Services.TryAddSingleton(); + builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton(sp => sp.GetRequiredService())); + + builder.Services.TryAddSingleton(); + builder.Services.TryAddSingleton(static sp => sp.GetRequiredService()); + builder.Services.TryAddSingleton(static sp => sp.GetRequiredService()); + + return builder; } /// diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferManager.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferManager.cs new file mode 100644 index 00000000000..16b51bf6528 --- /dev/null +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferManager.cs @@ -0,0 +1,87 @@ +// 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.Diagnostics.CodeAnalysis; +using Microsoft.AspNetCore.Diagnostics.Logging; +using Microsoft.AspNetCore.Http; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; + +namespace Microsoft.Extensions.Diagnostics.Buffering; +internal sealed class HttpRequestBufferManager : IHttpRequestBufferManager +{ + private readonly GlobalBufferManager _globalBufferManager; + private readonly IHttpContextAccessor _httpContextAccessor; + private readonly IOptionsMonitor _requestOptions; + private readonly IOptionsMonitor _globalOptions; + + public HttpRequestBufferManager( + GlobalBufferManager globalBufferManager, + IHttpContextAccessor httpContextAccessor, + IOptionsMonitor requestOptions, + IOptionsMonitor globalOptions) + { + _globalBufferManager = globalBufferManager; + _httpContextAccessor = httpContextAccessor; + _requestOptions = requestOptions; + _globalOptions = globalOptions; + } + + public ILoggingBuffer CreateBuffer(IBufferSink bufferSink, string category) + { + var httpContext = _httpContextAccessor.HttpContext; + if (httpContext is null) + { + return _globalBufferManager.CreateBuffer(bufferSink, category); + } + + if (!httpContext.Items.TryGetValue(category, out var buffer)) + { + var httpRequestBuffer = new HttpRequestBuffer(bufferSink, _requestOptions, _globalOptions); + httpContext.Items[category] = httpRequestBuffer; + return httpRequestBuffer; + } + + if (buffer is not ILoggingBuffer loggingBuffer) + { + throw new InvalidOperationException($"Unable to parse value of {buffer} of the {category}"); + } + + return loggingBuffer; + } + + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.ILoggingBuffer.Flush()")] + public void Flush() => _globalBufferManager.Flush(); + + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.ILoggingBuffer.Flush()")] + public void FlushCurrentRequestLogs() + { + if (_httpContextAccessor.HttpContext is not null) + { + foreach (var kvp in _httpContextAccessor.HttpContext!.Items) + { + if (kvp.Value is ILoggingBuffer buffer) + { + buffer.Flush(); + } + } + } + } + + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.ILoggingBuffer.TryEnqueue(LogLevel, String, EventId, TState, Exception, Func)")] + public bool TryEnqueue( + IBufferSink bufferSink, + LogLevel logLevel, + string category, + EventId eventId, + TState attributes, + Exception? exception, + Func formatter) + { + var buffer = CreateBuffer(bufferSink, category); + return buffer.TryEnqueue(logLevel, category, eventId, attributes, exception, formatter); + } +} +#endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferOptions.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferOptions.cs index cf04cd2da8c..cc266422026 100644 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferOptions.cs +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferOptions.cs @@ -17,24 +17,15 @@ namespace Microsoft.AspNetCore.Diagnostics.Logging; public class HttpRequestBufferOptions { /// - /// Gets or sets the time to suspend the buffer after flushing. + /// Gets or sets the duration to check and remove the buffered items exceeding the . /// - /// - /// 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. - /// - public TimeSpan SuspendAfterFlushDuration { get; set; } = TimeSpan.FromSeconds(30); + public TimeSpan PerRequestDuration { get; set; } = TimeSpan.FromSeconds(10); /// /// Gets or sets the size of the buffer for a request. /// public int PerRequestCapacity { get; set; } = 1_000; - /// - /// Gets or sets the size of the global buffer which applies to non-request logs only. - /// - public int GlobalCapacity { get; set; } = 1_000_000; - #pragma warning disable CA1002 // Do not expose generic lists - List is necessary to be able to call .AddRange() #pragma warning disable CA2227 // Collection properties should be read only - setter is necessary for options pattern /// diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferProvider.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferProvider.cs deleted file mode 100644 index 3ed5c08b1d7..00000000000 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferProvider.cs +++ /dev/null @@ -1,30 +0,0 @@ -// 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.Concurrent; -using Microsoft.AspNetCore.Http; -using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.Logging; - -namespace Microsoft.AspNetCore.Diagnostics.Logging; - -internal sealed class HttpRequestBufferProvider : ILoggingBufferProvider -{ - private readonly GlobalBufferProvider _globalBufferProvider; - private readonly IHttpContextAccessor _accessor; - private readonly ConcurrentDictionary _requestBuffers = new(); - - public HttpRequestBufferProvider(GlobalBufferProvider globalBufferProvider, IHttpContextAccessor accessor) - { - _globalBufferProvider = globalBufferProvider; - _accessor = accessor; - } - - public ILoggingBuffer CurrentBuffer => _accessor.HttpContext is null - ? _globalBufferProvider.CurrentBuffer - : _requestBuffers.GetOrAdd(_accessor.HttpContext.TraceIdentifier, _accessor.HttpContext.RequestServices.GetRequiredService()); - - // TO DO: Dispose request buffer when the respective HttpContext is disposed -} -#endif diff --git a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferedLogRecord.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferedLogRecord.cs deleted file mode 100644 index 8983e97843b..00000000000 --- a/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferedLogRecord.cs +++ /dev/null @@ -1,38 +0,0 @@ -// 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.AspNetCore.Diagnostics.Logging; - -internal sealed class HttpRequestBufferedLogRecord : BufferedLogRecord -{ - public HttpRequestBufferedLogRecord( - LogLevel logLevel, - EventId eventId, - IReadOnlyList> state, - Exception? exception, - string? formatter) - { - LogLevel = logLevel; - EventId = eventId; - Attributes = state; - Exception = exception?.ToString(); // wtf?? - FormattedMessage = formatter; - } - - public override IReadOnlyList> Attributes { get; } - public override string? FormattedMessage { get; } - public override string? Exception { get; } - - public override DateTimeOffset Timestamp { get; } - - public override LogLevel LogLevel { get; } - - public override EventId EventId { get; } -} -#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBufferProvider.cs b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IHttpRequestBufferManager.cs similarity index 53% rename from src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBufferProvider.cs rename to src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IHttpRequestBufferManager.cs index 52742297d0b..d237cd9cf51 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBufferProvider.cs +++ b/src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IHttpRequestBufferManager.cs @@ -1,21 +1,21 @@ // 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.Shared.DiagnosticIds; -namespace Microsoft.Extensions.Logging; +namespace Microsoft.Extensions.Diagnostics.Buffering; /// -/// Interface providing access to the current logging buffer. +/// Interface for a global buffer manager. /// [Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] -public interface ILoggingBufferProvider +public interface IHttpRequestBufferManager : IBufferManager { /// - /// Gets current logging buffer. + /// Flushes the buffer and emits buffered logs for the current request. /// - public ILoggingBuffer CurrentBuffer { get; } + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.ILoggingBuffer.Flush()")] + public void FlushCurrentRequestLogs(); } #endif diff --git a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogger.cs b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogger.cs index 9ba5586dba6..d3fb76cec0b 100644 --- a/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogger.cs +++ b/src/Libraries/Microsoft.Extensions.Diagnostics.Testing/Logging/FakeLogger.cs @@ -8,9 +8,10 @@ using System.Globalization; #if NET9_0_OR_GREATER using System.Diagnostics.CodeAnalysis; +using System.Text.Json; using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Shared.DiagnosticIds; - +using Microsoft.Shared.JsonExceptionConverter; #endif using Microsoft.Shared.Diagnostics; @@ -118,19 +119,20 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except #if NET9_0_OR_GREATER /// [Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] + [UnconditionalSuppressMessage("AOT", "IL3050:Calling members annotated with 'RequiresDynamicCodeAttribute' may break functionality when AOT compiling.", Justification = "")] public void LogRecords(IEnumerable records) { _ = Throw.IfNull(records); var l = new List(); - ScopeProvider.ForEachScope((scopeState, list) => list.Add(scopeState), l); foreach (var rec in records) { -#pragma warning disable CA2201 // TO DO: Remove suppression and implement propert Exception deserialization - var record = new FakeLogRecord(rec.LogLevel, rec.EventId, ConsumeTState(rec.Attributes), new Exception(rec.Exception), rec.FormattedMessage ?? string.Empty, +#pragma warning disable IL2026 // Members annotated with 'RequiresUnreferencedCodeAttribute' require dynamic access otherwise can break functionality when trimming application code + var exception = rec.Exception is not null ? JsonSerializer.Deserialize(rec.Exception, ExceptionConverter.JsonSerializerOptions) : null; +#pragma warning restore IL2026 // Members annotated with 'RequiresUnreferencedCodeAttribute' require dynamic access otherwise can break functionality when trimming application code + 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); -#pragma warning restore CA2201 Collector.AddRecord(record); } } 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..db21a9e64b9 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 @@ -11,6 +11,7 @@ true true true + true $(NoWarn);SYSLIB1100;SYSLIB1101 diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferSink.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferSink.cs new file mode 100644 index 00000000000..850bbb52277 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferSink.cs @@ -0,0 +1,94 @@ +// 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.Diagnostics.CodeAnalysis; +using System.Linq; +using System.Text.Json; +using Microsoft.Extensions.Diagnostics.Buffering; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.ObjectPool; +using Microsoft.Shared.JsonExceptionConverter; +using Microsoft.Shared.Pools; +using static Microsoft.Extensions.Logging.ExtendedLoggerFactory; + +namespace Microsoft.Extensions.Logging; +internal sealed class BufferSink : IBufferSink +{ + private readonly ExtendedLoggerFactory _factory; + private readonly string _category; + private readonly ObjectPool> _logRecordPool = PoolFactory.CreateListPool(); + + public BufferSink(ExtendedLoggerFactory factory, string category) + { + _factory = factory; + _category = category; + } + + [RequiresUnreferencedCode("Calls System.Text.Json.JsonSerializer.Deserialize(String, JsonSerializerOptions)")] + [UnconditionalSuppressMessage("AOT", "IL3050:Calling members annotated with 'RequiresDynamicCodeAttribute' may break functionality when AOT compiling.", Justification = "")] + public void LogRecords(IEnumerable serializedRecords) + where T : ISerializedLogRecord + { + var providers = _factory.ProviderRegistrations; + + List? pooledList = null; + try + { + foreach (var provider in providers) + { + var logger = provider.Provider.CreateLogger(_category); + + if (logger is IBufferedLogger bufferedLogger) + { + if (pooledList is null) + { + pooledList = _logRecordPool.Get(); + + foreach (var serializedRecord in serializedRecords) + { + pooledList.Add( + new PooledLogRecord( + serializedRecord.Timestamp, + serializedRecord.LogLevel, + serializedRecord.EventId, + serializedRecord.Exception, + serializedRecord.FormattedMessage, + serializedRecord.Attributes.Select(kvp => new KeyValuePair(kvp.Key, kvp.Value)).ToArray())); + } + } + + bufferedLogger.LogRecords(pooledList); + + } + else + { + foreach (var serializedRecord in serializedRecords) + { + Exception? exception = null; + if (serializedRecord.Exception is not null) + { + exception = JsonSerializer.Deserialize(serializedRecord.Exception, ExceptionConverter.JsonSerializerOptions); + } + + logger.Log( + serializedRecord.LogLevel, + serializedRecord.EventId, + serializedRecord.Attributes, + exception, + (_, _) => serializedRecord.FormattedMessage ?? string.Empty); + } + } + } + } + finally + { + if (pooledList is not null) + { + _logRecordPool.Return(pooledList); + } + } + } +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs index ffba82f84c6..57ae8da929d 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs @@ -4,113 +4,81 @@ #if NET9_0_OR_GREATER using System; using System.Collections.Concurrent; -using System.Collections.Generic; -using System.Threading; -using System.Threading.Tasks; +using System.Diagnostics.CodeAnalysis; using Microsoft.Extensions.Diagnostics; -using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Options; +using Microsoft.Shared.Diagnostics; +using static Microsoft.Extensions.Logging.ExtendedLogger; namespace Microsoft.Extensions.Logging; -internal sealed class GlobalBuffer : BackgroundService, ILoggingBuffer +internal sealed class GlobalBuffer : ILoggingBuffer { private readonly IOptionsMonitor _options; - private readonly ConcurrentDictionary> _buffers; - private readonly TimeProvider _timeProvider = TimeProvider.System; + private readonly ConcurrentQueue _buffer; + private readonly IBufferSink _bufferSink; + private readonly TimeProvider _timeProvider; private DateTimeOffset _lastFlushTimestamp; - public GlobalBuffer(IOptionsMonitor options) + public GlobalBuffer(IBufferSink bufferSink, IOptionsMonitor options, TimeProvider timeProvider) { _options = options; - _lastFlushTimestamp = _timeProvider.GetUtcNow(); - _buffers = new ConcurrentDictionary>(); - } - - internal GlobalBuffer(IOptionsMonitor options, TimeProvider timeProvider) - : this(options) - { _timeProvider = timeProvider; - _lastFlushTimestamp = _timeProvider.GetUtcNow(); + _buffer = new ConcurrentQueue(); + _bufferSink = bufferSink; } - public bool TryEnqueue( - IBufferedLogger logger, + [RequiresUnreferencedCode( + "Calls Microsoft.Extensions.Logging.SerializedLogRecord.SerializedLogRecord(LogLevel, EventId, DateTimeOffset, IReadOnlyList>, Exception, String)")] + public bool TryEnqueue( LogLevel logLevel, string category, EventId eventId, - IReadOnlyList> joiner, - Exception? exception, string formatter) + T attributes, + Exception? exception, + Func formatter) { if (!IsEnabled(category, logLevel, eventId)) { return false; } - var record = new GlobalBufferedLogRecord(logLevel, eventId, joiner, exception, formatter); - var queue = _buffers.GetOrAdd(logger, _ => new ConcurrentQueue()); - if (queue.Count >= _options.CurrentValue.Capacity) + switch (attributes) { - _ = queue.TryDequeue(out GlobalBufferedLogRecord? _); + case ModernTagJoiner modernTagJoiner: + _buffer.Enqueue(new SerializedLogRecord(logLevel, eventId, _timeProvider.GetUtcNow(), modernTagJoiner, exception, + ((Func)(object)formatter)(modernTagJoiner, exception))); + break; + case LegacyTagJoiner legacyTagJoiner: + _buffer.Enqueue(new SerializedLogRecord(logLevel, eventId, _timeProvider.GetUtcNow(), legacyTagJoiner, exception, + ((Func)(object)formatter)(legacyTagJoiner, exception))); + break; + default: + Throw.ArgumentException(nameof(attributes), $"Unsupported type of the log attributes object detected: {typeof(T)}"); + break; } - queue.Enqueue(record); - return true; } + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.BufferSink.LogRecords(IEnumerable)")] public void Flush() { - foreach (var (logger, queue) in _buffers) - { - var result = new List(); - while (!queue.IsEmpty) - { - if (queue.TryDequeue(out GlobalBufferedLogRecord? item)) - { - result.Add(item); - } - } - - logger.LogRecords(result); - } + var result = _buffer.ToArray(); + _buffer.Clear(); _lastFlushTimestamp = _timeProvider.GetUtcNow(); - } - internal void RemoveExpiredItems() - { - foreach (var (logger, queue) in _buffers) - { - while (!queue.IsEmpty) - { - if (queue.TryPeek(out GlobalBufferedLogRecord? item)) - { - if (_timeProvider.GetUtcNow() - item.Timestamp > _options.CurrentValue.Duration) - { - _ = queue.TryDequeue(out _); - } - else - { - break; - } - } - else - { - break; - } - } - } + _bufferSink.LogRecords(result); } - protected override async Task ExecuteAsync(CancellationToken cancellationToken) + public void TruncateOverlimit() { - while (!cancellationToken.IsCancellationRequested) + // Capacity is a soft limit, which might be exceeded, esp. in multi-threaded environments. + while (_buffer.Count > _options.CurrentValue.Capacity) { - await _timeProvider.Delay(_options.CurrentValue.Duration, cancellationToken).ConfigureAwait(false); - RemoveExpiredItems(); + _ = _buffer.TryDequeue(out _); } } diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggerBuilderExtensions.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggerBuilderExtensions.cs index 3789dc9c0f6..c4800c05af3 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggerBuilderExtensions.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferLoggerBuilderExtensions.cs @@ -7,6 +7,7 @@ using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.DependencyInjection.Extensions; +using Microsoft.Extensions.Diagnostics.Buffering; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; @@ -36,7 +37,7 @@ public static ILoggingBuilder AddGlobalBuffer(this ILoggingBuilder builder, ICon return builder .AddGlobalBufferConfiguration(configuration) - .AddGlobalBufferProvider(); + .AddGlobalBufferManager(); } /// @@ -56,26 +57,23 @@ public static ILoggingBuilder AddGlobalBuffer(this ILoggingBuilder builder, LogL .Configure(options => options.Rules.Add(new BufferFilterRule(null, level, null))) .Configure(configure ?? new Action(_ => { })); - return builder.AddGlobalBufferProvider(); + return builder.AddGlobalBufferManager(); } /// - /// Adds global logging buffer provider. + /// Adds global logging buffer manager. /// /// The . /// The so that additional calls can be chained. - public static ILoggingBuilder AddGlobalBufferProvider(this ILoggingBuilder builder) + internal static ILoggingBuilder AddGlobalBufferManager(this ILoggingBuilder builder) { _ = Throw.IfNull(builder); - builder.Services.TryAddSingleton(); - builder.Services.TryAddSingleton(static sp => sp.GetRequiredService()); + builder.Services.TryAddSingleton(); + builder.Services.TryAddSingleton(static sp => sp.GetRequiredService()); builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton()); - - builder.Services.TryAddSingleton(); - builder.Services.TryAddSingleton(static sp => sp.GetRequiredService()); - builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton(static sp => sp.GetRequiredService())); + builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton(static sp => sp.GetRequiredService())); return builder; } diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferManager.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferManager.cs new file mode 100644 index 00000000000..6a6cef25ce1 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferManager.cs @@ -0,0 +1,69 @@ +// 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.Diagnostics.CodeAnalysis; +using System.Threading; +using System.Threading.Tasks; +using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; + +namespace Microsoft.Extensions.Diagnostics.Buffering; +internal sealed class GlobalBufferManager : BackgroundService, IBufferManager +{ + internal readonly ConcurrentDictionary Buffers = []; + private readonly IOptionsMonitor _options; + private readonly TimeProvider _timeProvider = TimeProvider.System; + + public GlobalBufferManager(IOptionsMonitor options) + { + _options = options; + } + + internal GlobalBufferManager(IOptionsMonitor options, TimeProvider timeProvider) + { + _timeProvider = timeProvider; + _options = options; + } + + public ILoggingBuffer CreateBuffer(IBufferSink bufferSink, string category) + => Buffers.GetOrAdd(category, _ => new GlobalBuffer(bufferSink, _options, _timeProvider)); + + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.ILoggingBuffer.Flush()")] + public void Flush() + { + foreach (var buffer in Buffers.Values) + { + buffer.Flush(); + } + } + + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.ILoggingBuffer.TryEnqueue(LogLevel, String, EventId, TState, Exception, Func)")] + public bool TryEnqueue( + IBufferSink bufferSink, + LogLevel logLevel, + string category, + EventId eventId, TState attributes, + Exception? exception, + Func formatter) + { + var buffer = CreateBuffer(bufferSink, category); + return buffer.TryEnqueue(logLevel, category, eventId, attributes, exception, formatter); + } + + protected override async Task ExecuteAsync(CancellationToken cancellationToken) + { + while (!cancellationToken.IsCancellationRequested) + { + await _timeProvider.Delay(_options.CurrentValue.Duration, cancellationToken).ConfigureAwait(false); + foreach (var buffer in Buffers.Values) + { + buffer.TruncateOverlimit(); + } + } + } + +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs index 7c15a8f3b9b..19009fb9a0d 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs @@ -25,14 +25,14 @@ public class GlobalBufferOptions public TimeSpan SuspendAfterFlushDuration { get; set; } = TimeSpan.FromSeconds(30); /// - /// Gets or sets the duration to keep logs in the buffer. + /// Gets or sets the duration to check and remove the buffered items exceeding the . /// public TimeSpan Duration { get; set; } = TimeSpan.FromSeconds(30); /// /// Gets or sets the size of the buffer. /// - public int Capacity { get; set; } = 1_000_000; + public int Capacity { get; set; } = 10_000; #pragma warning disable CA1002 // Do not expose generic lists - List is necessary to be able to call .AddRange() #pragma warning disable CA2227 // Collection properties should be read only - setter is necessary for options pattern diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferProvider.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferProvider.cs deleted file mode 100644 index 5bfedc32516..00000000000 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferProvider.cs +++ /dev/null @@ -1,18 +0,0 @@ -// 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.Logging; - -internal sealed class GlobalBufferProvider : ILoggingBufferProvider -{ - private readonly GlobalBuffer _buffer; - - public GlobalBufferProvider(GlobalBuffer buffer) - { - _buffer = buffer; - } - - public ILoggingBuffer CurrentBuffer => _buffer; -} -#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferedLogRecord.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferedLogRecord.cs deleted file mode 100644 index e72fc3bed2f..00000000000 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferedLogRecord.cs +++ /dev/null @@ -1,38 +0,0 @@ -// 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.Logging; - -internal sealed class GlobalBufferedLogRecord : BufferedLogRecord -{ - public GlobalBufferedLogRecord( - LogLevel logLevel, - EventId eventId, - IReadOnlyList> state, - Exception? exception, - string? formatter) - { - LogLevel = logLevel; - EventId = eventId; - Attributes = state; - Exception = exception?.ToString(); // wtf?? - FormattedMessage = formatter; - } - - public override IReadOnlyList> Attributes { get; } - public override string? FormattedMessage { get; } - public override string? Exception { get; } - - public override DateTimeOffset Timestamp { get; } - - public override LogLevel LogLevel { get; } - - public override EventId EventId { get; } -} -#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/IBufferManager.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/IBufferManager.cs new file mode 100644 index 00000000000..2905c9b269c --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/IBufferManager.cs @@ -0,0 +1,46 @@ +// 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.Logging; +using Microsoft.Shared.DiagnosticIds; + +namespace Microsoft.Extensions.Diagnostics.Buffering; + +/// +/// Interface for a global buffer manager. +/// +[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] +public interface IBufferManager +{ + /// + /// Flushes the buffer and emits all buffered logs. + /// + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.ILoggingBuffer.Flush()")] + void Flush(); + + /// + /// Enqueues a log record in the underlying buffer. + /// + /// Buffer sink. + /// Log level. + /// Category. + /// Event ID. + /// Attributes. + /// Exception. + /// Formatter delegate. + /// Type of the instance. + /// if the log record was buffered; otherwise, . + [RequiresUnreferencedCode( + "Calls Microsoft.Extensions.Logging.SerializedLogRecord.SerializedLogRecord(LogLevel, EventId, DateTimeOffset, IReadOnlyList>, Exception, String)")] + bool TryEnqueue( + IBufferSink bufferSink, + LogLevel logLevel, + string category, + EventId eventId, + TState attributes, + Exception? exception, + Func formatter); +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/IBufferSink.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/IBufferSink.cs new file mode 100644 index 00000000000..757f9d2b111 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/IBufferSink.cs @@ -0,0 +1,25 @@ +// 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.Shared.DiagnosticIds; + +namespace Microsoft.Extensions.Logging; + +/// +/// Interface for a buffer sink. +/// +[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] +public interface IBufferSink +{ + /// + /// Forward the to all currently registered loggers. + /// + /// serialized log records. + /// Type of the log records. + [RequiresUnreferencedCode("Calls System.Text.Json.JsonSerializer.Deserialize(String, JsonSerializerOptions)")] + void LogRecords(IEnumerable serializedRecords) + where T : ISerializedLogRecord; +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBuffer.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBuffer.cs index baf15325156..a25d249d5d7 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBuffer.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBuffer.cs @@ -3,36 +3,46 @@ #if NET9_0_OR_GREATER using System; -using System.Collections.Generic; using System.Diagnostics.CodeAnalysis; using Microsoft.Extensions.Logging; -using Microsoft.Extensions.Logging.Abstractions; -using Microsoft.Shared.DiagnosticIds; namespace Microsoft.Extensions.Logging; /// /// Interface for a logging buffer. /// -[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] -public interface ILoggingBuffer +internal interface ILoggingBuffer { /// - /// Flushes the buffer and emits all buffered logs. + /// Enqueues a log record in the underlying buffer.. /// - void Flush(); - - /// - /// Enqueues a log record. - /// - /// true or false. - bool TryEnqueue( - IBufferedLogger logger, + /// Log level. + /// Category. + /// Event ID. + /// Attributes. + /// Exception. + /// Formatter delegate. + /// Type of the instance. + /// if the log record was buffered; otherwise, . + [RequiresUnreferencedCode( + "Calls Microsoft.Extensions.Logging.SerializedLogRecord.SerializedLogRecord(LogLevel, EventId, DateTimeOffset, IReadOnlyList>, Exception, String)")] + bool TryEnqueue( LogLevel logLevel, string category, EventId eventId, - IReadOnlyList> joiner, + TState attributes, Exception? exception, - string formatter); + Func formatter); + + /// + /// Flushes the buffer. + /// + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.BufferSink.LogRecords(IEnumerable)")] + void Flush(); + + /// + /// Removes items exceeding the buffer limit. + /// + void TruncateOverlimit(); } #endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ISerializedLogRecord.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ISerializedLogRecord.cs new file mode 100644 index 00000000000..23f03323893 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ISerializedLogRecord.cs @@ -0,0 +1,46 @@ +// 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.CodeAnalysis; +using Microsoft.Shared.DiagnosticIds; + +namespace Microsoft.Extensions.Logging; + +/// +/// Represents a buffered log record that has been serialized. +/// +[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)] +public interface ISerializedLogRecord +{ + /// + /// Gets the time when the log record was first created. + /// + public DateTimeOffset Timestamp { get; } + + /// + /// Gets the record's logging severity level. + /// + public LogLevel LogLevel { get; } + + /// + /// Gets the record's event id. + /// + public EventId EventId { get; } + + /// + /// Gets an exception string for this record. + /// + public string? Exception { get; } + + /// + /// Gets the formatted log message. + /// + public string? FormattedMessage { get; } + + /// + /// Gets the variable set of name/value pairs associated with the record. + /// + public IReadOnlyList> Attributes { get; } +} diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/PooledLogRecord.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/PooledLogRecord.cs new file mode 100644 index 00000000000..e20bc1069a3 --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/PooledLogRecord.cs @@ -0,0 +1,76 @@ +// 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.Diagnostics; +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.ObjectPool; + +namespace Microsoft.Extensions.Diagnostics.Buffering; +internal sealed class PooledLogRecord : BufferedLogRecord, IResettable +{ + public PooledLogRecord( + 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 ActivitySpanId? ActivitySpanId => _activitySpanId; + private ActivitySpanId? _activitySpanId; + + public override ActivityTraceId? ActivityTraceId => _activityTraceId; + private ActivityTraceId? _activityTraceId; + + public override int? ManagedThreadId => _managedThreadId; + private int? _managedThreadId; + + public override string? FormattedMessage => _formattedMessage; + private string? _formattedMessage; + + public override string? MessageTemplate => _messageTemplate; + private string? _messageTemplate; + + public override IReadOnlyList> Attributes => _attributes; + private IReadOnlyList> _attributes; + + public bool TryReset() + { + _timestamp = default; + _logLevel = default; + _eventId = default; + _exception = default; + _activitySpanId = default; + _activityTraceId = default; + _managedThreadId = default; + _formattedMessage = default; + _messageTemplate = default; + _attributes = []; + + return true; + } +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/SerializedLogRecord.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/SerializedLogRecord.cs new file mode 100644 index 00000000000..7aa9df3056f --- /dev/null +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Buffering/SerializedLogRecord.cs @@ -0,0 +1,53 @@ +// 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.Diagnostics.CodeAnalysis; +using System.Text.Json; +using Microsoft.Extensions.Logging; +using Microsoft.Shared.JsonExceptionConverter; + +namespace Microsoft.Extensions.Logging; + +internal readonly struct SerializedLogRecord : ISerializedLogRecord +{ + [RequiresUnreferencedCode("Calls System.Text.Json.JsonSerializer.Serialize(TValue, JsonSerializerOptions)")] + [UnconditionalSuppressMessage("AOT", "IL3050:Calling members annotated with 'RequiresDynamicCodeAttribute' may break functionality when AOT compiling.", Justification = "")] + public SerializedLogRecord( + LogLevel logLevel, + EventId eventId, + DateTimeOffset timestamp, + IReadOnlyList> attributes, + Exception? exception, + string formattedMessage) + { + LogLevel = logLevel; + EventId = eventId; + Timestamp = timestamp; + + var serializedAttributes = new List>(attributes.Count); + for (int i = 0; i < attributes.Count; i++) + { + serializedAttributes.Add(new KeyValuePair(new string(attributes[i].Key), attributes[i].Value?.ToString() ?? string.Empty)); + } + + Attributes = serializedAttributes; + + // Serialize without StackTrace, whis is already optionally available in the log attributes via the ExtendedLogger. + Exception = JsonSerializer.Serialize(exception, ExceptionConverter.JsonSerializerOptions); + FormattedMessage = formattedMessage; + } + + public IReadOnlyList> Attributes { get; } + public string? FormattedMessage { get; } + public string? Exception { get; } + + public DateTimeOffset Timestamp { get; } + + public LogLevel LogLevel { get; } + + public EventId EventId { get; } +} +#endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs index b39803404dc..18675854551 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs @@ -4,8 +4,9 @@ using System; using System.Collections.Generic; using System.Diagnostics; +using System.Diagnostics.CodeAnalysis; #if NET9_0_OR_GREATER -using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Diagnostics.Buffering; #endif using Microsoft.Shared.Pools; @@ -33,13 +34,36 @@ internal sealed partial class ExtendedLogger : ILogger public MessageLogger[] MessageLoggers { get; set; } = Array.Empty(); public ScopeLogger[] ScopeLoggers { get; set; } = Array.Empty(); +#if NET9_0_OR_GREATER + private readonly IBufferManager? _bufferManager; + private readonly IBufferSink? _bufferSink; + + public ExtendedLogger(ExtendedLoggerFactory factory, LoggerInformation[] loggers) + { + _factory = factory; + Loggers = loggers; + + _bufferManager = _factory.Config.BufferManager; + if (_bufferManager is not null) + { + Debug.Assert(loggers.Length > 0, "There should be at least one logger provider."); + + _bufferSink = new BufferSink(factory, loggers[0].Category); + } + } + +#else public ExtendedLogger(ExtendedLoggerFactory factory, LoggerInformation[] loggers) { _factory = factory; Loggers = loggers; } +#endif + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.ExtendedLogger.ModernPath(LogLevel, EventId, LoggerMessageState, Exception, Func)")] +#pragma warning disable IL2046 // 'RequiresUnreferencedCodeAttribute' annotations must match across all interface implementations or overrides. public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) +#pragma warning restore IL2046 // 'RequiresUnreferencedCodeAttribute' annotations must match across all interface implementations or overrides. { if (typeof(TState) == typeof(LoggerMessageState)) { @@ -207,6 +231,7 @@ void HandleException(Exception exception, int indent) } } + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.ILoggingBuffer.TryEnqueue(LogLevel, String, EventId, TState, Exception, Func)")] private void ModernPath(LogLevel logLevel, EventId eventId, LoggerMessageState msgState, Exception? exception, Func formatter) { var loggers = MessageLoggers; @@ -263,21 +288,35 @@ private void ModernPath(LogLevel logLevel, EventId eventId, LoggerMessageState m RecordException(exception, joiner.EnrichmentTagCollector, config); } +#if NET9_0_OR_GREATER + bool? shouldBuffer = null; +#endif for (int i = 0; i < loggers.Length; i++) { ref readonly MessageLogger loggerInfo = ref loggers[i]; if (loggerInfo.IsNotFilteredOut(logLevel)) { #if NET9_0_OR_GREATER - if (loggerInfo.Logger is IBufferedLogger bufferedLogger) + if (shouldBuffer is null or true) { - if (config.BufferProvider is not null && - config.BufferProvider.CurrentBuffer.TryEnqueue(bufferedLogger, logLevel, loggerInfo.Category!, eventId, joiner, exception, joiner.Formatter!(joiner.State, exception))) + if (_bufferManager is not null) { + var result = _bufferManager.TryEnqueue(_bufferSink!, logLevel, loggerInfo.Category!, eventId, joiner, exception, static (s, e) => + { + var fmt = s.Formatter!; + return fmt(s.State!, e); + }); + shouldBuffer = result; + // The record was buffered, so we skip logging it for now. - // When a caller needs to flush the buffer and calls ILoggerBuffer.Flush(), - // the buffer will internally call IBufferedLogger.LogRecords to emit log records. + // When a caller needs to flush the buffer and calls IBufferManager.Flush(), + // the buffer manager will internally call IBufferedLogger.LogRecords to emit log records. continue; + + } + else + { + shouldBuffer = false; } } #endif @@ -311,6 +350,7 @@ private void ModernPath(LogLevel logLevel, EventId eventId, LoggerMessageState m HandleExceptions(exceptions); } + [RequiresUnreferencedCode("Calls Microsoft.Extensions.Logging.ILoggingBuffer.TryEnqueue(LogLevel, String, EventId, TState, Exception, Func)")] private void LegacyPath(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { var loggers = MessageLoggers; @@ -360,24 +400,35 @@ private void LegacyPath(LogLevel logLevel, EventId eventId, TState state { RecordException(exception, joiner.EnrichmentTagCollector, config); } - +#if NET9_0_OR_GREATER + bool? shouldBuffer = null; +#endif for (int i = 0; i < loggers.Length; i++) { ref readonly MessageLogger loggerInfo = ref loggers[i]; if (loggerInfo.IsNotFilteredOut(logLevel)) { #if NET9_0_OR_GREATER - if (loggerInfo.Logger is IBufferedLogger bufferedLogger) + if (shouldBuffer is null or true) { - if (config.BufferProvider is not null && - config.BufferProvider.CurrentBuffer.TryEnqueue( - bufferedLogger, logLevel, loggerInfo.Category!, eventId, joiner, exception, - ((Func)joiner.Formatter)((TState)joiner.State!, exception))) + if (_bufferManager is not null) { + var result = _bufferManager.TryEnqueue(_bufferSink!, logLevel, loggerInfo.Category!, eventId, joiner, exception, static (s, e) => + { + var fmt = (Func)s.Formatter!; + return fmt((TState)s.State!, e); + }); + shouldBuffer = result; + // The record was buffered, so we skip logging it for now. - // When a caller needs to flush the buffer and calls ILoggerBuffer.Flush(), - // the buffer will internally call IBufferedLogger.LogRecords to emit log records. + // When a caller needs to flush the buffer and calls IBufferManager.Flush(), + // the buffer manager will internally call IBufferedLogger.LogRecords to emit log records. continue; + + } + else + { + shouldBuffer = false; } } #endif diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLoggerFactory.cs b/src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLoggerFactory.cs index 1ea4f0dc0b3..8d2b4923d4c 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,13 +27,14 @@ internal sealed class ExtendedLoggerFactory : ILoggerFactory private readonly IDisposable? _redactionOptionsChangeTokenRegistration; private readonly Action[] _enrichers; #if NET9_0_OR_GREATER - private readonly ILoggingBufferProvider? _bufferProvider; + private readonly IBufferManager? _bufferManager; #endif private readonly KeyValuePair[] _staticTags; private readonly Func _redactorProvider; private volatile bool _disposed; private LoggerFilterOptions _filterOptions; private IExternalScopeProvider? _scopeProvider; + public IReadOnlyCollection ProviderRegistrations => _providerRegistrations; #pragma warning disable S107 // Methods should not have too many parameters public ExtendedLoggerFactory( @@ -44,7 +48,7 @@ public ExtendedLoggerFactory( IOptionsMonitor? redactionOptions = null, #if NET9_0_OR_GREATER IRedactorProvider? redactorProvider = null, - ILoggingBufferProvider? bufferProvider = null) + IBufferManager? bufferManager = null) #else IRedactorProvider? redactorProvider = null) #endif @@ -52,7 +56,7 @@ public ExtendedLoggerFactory( { _scopeProvider = scopeProvider; #if NET9_0_OR_GREATER - _bufferProvider = bufferProvider; + _bufferManager = bufferManager; #endif _factoryOptions = factoryOptions == null || factoryOptions.Value == null ? new LoggerFactoryOptions() : factoryOptions.Value; @@ -302,7 +306,7 @@ private LoggerConfig ComputeConfig(LoggerEnrichmentOptions? enrichmentOptions, L _redactorProvider, #if NET9_0_OR_GREATER redactionOptions.ApplyDiscriminator, - _bufferProvider); + _bufferManager); #else redactionOptions.ApplyDiscriminator); #endif @@ -311,7 +315,7 @@ private LoggerConfig ComputeConfig(LoggerEnrichmentOptions? enrichmentOptions, L 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 fba961defd5..c84ba772e86 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; @@ -22,7 +25,7 @@ public LoggerConfig( Func getRedactor, #if NET9_0_OR_GREATER bool addRedactionDiscriminator, - ILoggingBufferProvider? bufferProvider) + IBufferManager? bufferManager) #else bool addRedactionDiscriminator) #endif @@ -37,7 +40,7 @@ public LoggerConfig( GetRedactor = getRedactor; AddRedactionDiscriminator = addRedactionDiscriminator; #if NET9_0_OR_GREATER - BufferProvider = bufferProvider; + BufferManager = bufferManager; #endif } @@ -50,6 +53,6 @@ public LoggerConfig( public Func GetRedactor { get; } public bool AddRedactionDiscriminator { get; } #if NET9_0_OR_GREATER - public ILoggingBufferProvider? BufferProvider { get; } + public IBufferManager? BufferManager { get; } #endif } diff --git a/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.csproj b/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.csproj index f303698ed82..fd344853ab2 100644 --- a/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.csproj +++ b/src/Libraries/Microsoft.Extensions.Telemetry/Microsoft.Extensions.Telemetry.csproj @@ -16,6 +16,7 @@ true true true + true true true diff --git a/src/Shared/JsonExceptionConverter/ExceptionConverter.cs b/src/Shared/JsonExceptionConverter/ExceptionConverter.cs new file mode 100644 index 00000000000..7b62eb81528 --- /dev/null +++ b/src/Shared/JsonExceptionConverter/ExceptionConverter.cs @@ -0,0 +1,171 @@ +// 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.Diagnostics.CodeAnalysis; +using System.Linq; +using System.Text.Json; +using System.Text.Json.Serialization; + +#pragma warning disable CA1716 +namespace Microsoft.Shared.JsonExceptionConverter; +#pragma warning restore CA1716 + +internal sealed class ExceptionConverter : JsonConverter +{ +#pragma warning disable CA2201 // Do not raise reserved exception types + private static Exception _failedDeserialization = new Exception("Failed to deserialize the exception object."); +#pragma warning restore CA2201 // Do not raise reserved exception types + + [UnconditionalSuppressMessage("AOT", "IL3050:Calling members annotated with 'RequiresDynamicCodeAttribute' may break functionality when AOT compiling.", Justification = "")] + public override Exception Read(ref Utf8JsonReader reader, Type typeToConvert, JsonSerializerOptions options) + { + if (reader.TokenType != JsonTokenType.StartObject) + { + return _failedDeserialization; + } + + return DeserializeException(ref reader); + } + + public override void Write(Utf8JsonWriter writer, Exception exception, JsonSerializerOptions options) + { + HandleException(writer, exception); + } + + public static readonly JsonSerializerOptions JsonSerializerOptions = new() + { + Converters = { new ExceptionConverter() } + }; + + public override bool CanConvert(Type typeToConvert) => typeof(Exception).IsAssignableFrom(typeToConvert); + + private static Exception DeserializeException(ref Utf8JsonReader reader) + { + string? type = null; + string? message = null; + string? source = null; + Exception? innerException = null; + List? innerExceptions = null; + + while (reader.Read()) + { + if (reader.TokenType == JsonTokenType.PropertyName) + { + string? propertyName = reader.GetString(); + _ = reader.Read(); + + switch (propertyName) + { + case "Type": + type = reader.GetString(); + break; + case "Message": + message = reader.GetString(); + break; + case "Source": + source = reader.GetString(); + break; + case "InnerException": + if (reader.TokenType == JsonTokenType.StartObject) + { + innerException = DeserializeException(ref reader); + } + + break; + case "InnerExceptions": + innerExceptions = new List(); + if (reader.TokenType == JsonTokenType.StartArray) + { + while (reader.Read() && reader.TokenType != JsonTokenType.EndArray) + { + if (reader.TokenType == JsonTokenType.StartObject) + { + var innerEx = DeserializeException(ref reader); + innerExceptions.Add(innerEx); + } + } + } + + break; + } + } + else if (reader.TokenType == JsonTokenType.EndObject) + { + break; + } + } + + if (type is null) + { + return _failedDeserialization; + } + +#pragma warning disable IL2057 // Unrecognized value passed to the parameter of method. It's not possible to guarantee the availability of the target type. + Type? deserializedType = Type.GetType(type); +#pragma warning restore IL2057 // Unrecognized value passed to the parameter of method. It's not possible to guarantee the availability of the target type. + if (deserializedType is null) + { + return _failedDeserialization; + } + + Exception? exception; + + if (innerExceptions != null && innerExceptions.Count > 0) + { + if (deserializedType == typeof(AggregateException)) + { + exception = new AggregateException(message, innerExceptions); + } + else + { + exception = Activator.CreateInstance(deserializedType, message, innerExceptions.First()) as Exception; + } + } + else if (innerException != null) + { + exception = Activator.CreateInstance(deserializedType, message, innerException) as Exception; + } + else + { + exception = Activator.CreateInstance(deserializedType, message) as Exception; + } + + if (exception == null) + { + return _failedDeserialization; + } + + exception.Source = source; + + return exception; + } + + private static void HandleException(Utf8JsonWriter writer, Exception exception) + { + writer.WriteStartObject(); + writer.WriteString("Type", exception.GetType().FullName); + writer.WriteString("Message", exception.Message); + writer.WriteString("Source", exception.Source); + if (exception is AggregateException aggregateException) + { + writer.WritePropertyName("InnerExceptions"); + writer.WriteStartArray(); + foreach (var ex in aggregateException.InnerExceptions) + { + HandleException(writer, ex); + } + + writer.WriteEndArray(); + } + else if (exception.InnerException != null) + { + writer.WritePropertyName("InnerException"); + HandleException(writer, exception.InnerException); + } + + writer.WriteEndObject(); + } +} +#endif diff --git a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/HttpRequestBufferLoggerBuilderExtensionsTests.cs b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/HttpRequestBufferLoggerBuilderExtensionsTests.cs index e389d65c57b..76162297cf7 100644 --- a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/HttpRequestBufferLoggerBuilderExtensionsTests.cs +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Buffering/HttpRequestBufferLoggerBuilderExtensionsTests.cs @@ -6,6 +6,7 @@ using System.Collections.Generic; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Diagnostics.Buffering; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; using Xunit; @@ -15,33 +16,19 @@ namespace Microsoft.AspNetCore.Diagnostics.Logging.Test; public class HttpRequestBufferLoggerBuilderExtensionsTests { [Fact] - public void AddHttpRequestBuffer_RegistersInDI() + public void AddHttpRequestBuffering_RegistersInDI() { var serviceCollection = new ServiceCollection(); serviceCollection.AddLogging(builder => { - builder.AddHttpRequestBuffer(LogLevel.Warning); + builder.AddHttpRequestBuffering(LogLevel.Warning); }); var serviceProvider = serviceCollection.BuildServiceProvider(); - var buffer = serviceProvider.GetService(); + var buffer = serviceProvider.GetService(); Assert.NotNull(buffer); - Assert.IsAssignableFrom(buffer); - } - - [Fact] - public void AddHttpRequestBufferProvider_RegistersInDI() - { - var serviceCollection = new ServiceCollection(); - serviceCollection.AddLogging(builder => - { - builder.AddHttpRequestBufferProvider(); - }); - var serviceProvider = serviceCollection.BuildServiceProvider(); - var bufferProvider = serviceProvider.GetService(); - Assert.NotNull(bufferProvider); - Assert.IsAssignableFrom(bufferProvider); + Assert.IsAssignableFrom(buffer); } [Fact] @@ -50,9 +37,8 @@ public void WhenArgumentNull_Throws() var builder = null as ILoggingBuilder; var configuration = null as IConfiguration; - Assert.Throws(() => builder!.AddHttpRequestBuffer(LogLevel.Warning)); - Assert.Throws(() => builder!.AddHttpRequestBuffer(configuration!)); - Assert.Throws(() => builder!.AddHttpRequestBufferProvider()); + Assert.Throws(() => builder!.AddHttpRequestBuffering(LogLevel.Warning)); + Assert.Throws(() => builder!.AddHttpRequestBuffering(configuration!)); } [Fact] 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 6856b9751a8..5bb7f99cc43 100644 --- a/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/AcceptanceTests.cs +++ b/test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/AcceptanceTests.cs @@ -26,7 +26,7 @@ using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Testing; #if NET9_0_OR_GREATER -using Microsoft.Extensions.Options; +using Microsoft.Extensions.Diagnostics.Buffering; #endif using Microsoft.Extensions.Time.Testing; using Microsoft.Net.Http.Headers; @@ -59,6 +59,31 @@ public static void Configure(IApplicationBuilder app) app.UseRouting(); app.UseHttpLogging(); +#if NET9_0_OR_GREATER + app.Map("/flushrequestlogs", static x => + x.Run(static async context => + { + await context.Request.Body.DrainAsync(default); + + // normally, this would be a Middleware and IHttpRequestBufferManager would be injected via constructor + var bufferManager = context.RequestServices.GetService(); + bufferManager?.FlushCurrentRequestLogs(); + })); + + app.Map("/flushalllogs", static x => + x.Run(static async context => + { + await context.Request.Body.DrainAsync(default); + + // normally, this would be a Middleware and IHttpRequestBufferManager would be injected via constructor + var bufferManager = context.RequestServices.GetService(); + if (bufferManager is not null) + { + bufferManager.FlushCurrentRequestLogs(); + bufferManager.Flush(); + } + })); +#endif app.Map("/error", static x => x.Run(static async context => { @@ -722,40 +747,39 @@ await RunAsync( [Fact] public async Task HttpRequestBuffering() { - var clock = new FakeTimeProvider(TimeProvider.System.GetUtcNow()); - - HttpRequestBufferOptions options = new() - { - SuspendAfterFlushDuration = TimeSpan.FromSeconds(0), - Rules = new List - { - new(null, LogLevel.Information, null), - } - }; - var buffer = new HttpRequestBuffer(new StaticOptionsMonitor(options), clock); - await RunAsync( - LogLevel.Information, - services => services.AddLogging(builder => + LogLevel.Trace, + services => services + .AddLogging(builder => { - builder.Services.AddScoped(sp => buffer); - builder.Services.AddScoped(sp => buffer); - builder.AddHttpRequestBuffer(LogLevel.Information); + // enable Microsoft.AspNetCore.Routing.Matching.DfaMatcher debug logs + // which we are produced by ASP.NET Core within HTTP context: + builder.AddFilter("Microsoft.AspNetCore.Routing.Matching.DfaMatcher", LogLevel.Debug); + + builder.AddHttpRequestBuffering(LogLevel.Debug); }), async (logCollector, client, sp) => { - using var response = await client.GetAsync("/home").ConfigureAwait(false); - + // just HTTP request logs: + using var response = await client.GetAsync("/flushrequestlogs").ConfigureAwait(false); Assert.True(response.IsSuccessStatusCode); - - Assert.Equal(0, logCollector.Count); - - using var scope = sp.CreateScope(); - var buffer = scope.ServiceProvider.GetRequiredService(); - buffer.Flush(); - 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(); + var logger = loggerFactory.CreateLogger("test"); + logger.LogTrace("This is a log message"); + using var response2 = await client.GetAsync("/flushalllogs").ConfigureAwait(false); + Assert.True(response2.IsSuccessStatusCode); + await WaitForLogRecordsAsync(logCollector, _defaultLogTimeout); + + // 1 and 2 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); }); } #endif @@ -803,19 +827,5 @@ private class ThrowingEnricher : IHttpLogEnricher { public void Enrich(IEnrichmentTagCollector collector, HttpContext httpContext) => throw new InvalidOperationException(); } - -#if NET9_0_OR_GREATER - private sealed class StaticOptionsMonitor : IOptionsMonitor - { - public StaticOptionsMonitor(T currentValue) - { - CurrentValue = currentValue; - } - - public IDisposable? OnChange(Action listener) => null; - public T Get(string? name) => CurrentValue; - public T CurrentValue { get; } - } -#endif } #endif diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/ExceptionConverterTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/ExceptionConverterTests.cs new file mode 100644 index 00000000000..8233f29a322 --- /dev/null +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/ExceptionConverterTests.cs @@ -0,0 +1,89 @@ +// 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.Text.Json; +using Microsoft.Shared.JsonExceptionConverter; +using Xunit; + +namespace Microsoft.Extensions.Logging.Test; + +public class ExceptionConverterTests +{ + private static readonly JsonSerializerOptions _options = new() + { + Converters = { new ExceptionConverter() } + }; + + [Fact] + public void SerializeAndDeserialize_SimpleException() + { + var options = new JsonSerializerOptions(); + options.Converters.Add(new ExceptionConverter()); + + // Arrange + var exception = new InvalidOperationException("Test exception"); + + // Act + var json = JsonSerializer.Serialize(exception, options); + var deserializedException = JsonSerializer.Deserialize(json, options); + + // Assert + Assert.NotNull(deserializedException); + Assert.IsType(deserializedException); + Assert.Equal(exception.Message, deserializedException.Message); + } + + [Fact] + public void SerializeAndDeserialize_ExceptionWithInnerException() + { + // Arrange + var innerException = new ArgumentNullException("paramName", "Inner exception message"); + var exception = new InvalidOperationException("Test exception with inner exception", innerException); + + // Act + var json = JsonSerializer.Serialize(exception, _options); + var deserializedException = JsonSerializer.Deserialize(json, _options); + + // Assert + Assert.NotNull(deserializedException); + Assert.IsType(deserializedException); + Assert.Equal(exception.Message, deserializedException.Message); + + Assert.NotNull(deserializedException.InnerException); + Assert.IsType(deserializedException.InnerException); + Assert.Contains(innerException.Message, deserializedException.InnerException.Message); + } + + [Fact] + public void SerializeAndDeserialize_AggregateException() + { + // Arrange + var innerException1 = new ArgumentException("First inner exception"); +#pragma warning disable CA2201 // Do not raise reserved exception types + var innerException2 = new NullReferenceException("Second inner exception"); +#pragma warning restore CA2201 // Do not raise reserved exception types + var exception = new AggregateException("Aggregate exception message", innerException1, innerException2); + + // Act + var json = JsonSerializer.Serialize(exception, _options); + var deserializedException = JsonSerializer.Deserialize(json, _options); + + // Assert + Assert.NotNull(deserializedException); + Assert.IsType(deserializedException); + Assert.Contains(exception.Message, deserializedException.Message); + + var aggregateException = (AggregateException)deserializedException; + Assert.NotNull(aggregateException.InnerExceptions); + Assert.Equal(2, aggregateException.InnerExceptions.Count); + + Assert.IsType(aggregateException.InnerExceptions[0]); + Assert.Equal(innerException1.Message, aggregateException.InnerExceptions[0].Message); + + Assert.IsType(aggregateException.InnerExceptions[1]); + Assert.Equal(innerException2.Message, aggregateException.InnerExceptions[1].Message); + } +} +#endif diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferLoggerBuilderExtensionsTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferLoggerBuilderExtensionsTests.cs index be6b42197d3..e28b8b246b8 100644 --- a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferLoggerBuilderExtensionsTests.cs +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferLoggerBuilderExtensionsTests.cs @@ -6,6 +6,7 @@ using System.Collections.Generic; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Diagnostics.Buffering; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; using Xunit; @@ -24,10 +25,10 @@ public void AddGlobalBuffer_RegistersInDI() }); var serviceProvider = serviceCollection.BuildServiceProvider(); - var buffer = serviceProvider.GetService(); + var bufferManager = serviceProvider.GetService(); - Assert.NotNull(buffer); - Assert.IsAssignableFrom(buffer); + Assert.NotNull(bufferManager); + Assert.IsAssignableFrom(bufferManager); } [Fact] @@ -38,7 +39,6 @@ public void WhenArgumentNull_Throws() Assert.Throws(() => builder!.AddGlobalBuffer(LogLevel.Warning)); Assert.Throws(() => builder!.AddGlobalBuffer(configuration!)); - Assert.Throws(() => builder!.AddGlobalBufferProvider()); } [Fact] diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs index 7410a2e0954..8b7cb598d1f 100644 --- a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs @@ -10,7 +10,7 @@ using Microsoft.Extensions.Logging.Testing; using Microsoft.Extensions.Options; #if NET9_0_OR_GREATER -using Microsoft.Extensions.Time.Testing; +using Microsoft.Extensions.Diagnostics.Buffering; #endif using Moq; using Xunit; @@ -124,52 +124,30 @@ public static void FeatureEnablement(bool enableRedaction, bool enableEnrichment #if NET9_0_OR_GREATER [Fact] - public static void GlobalBuffering() + public static void GlobalBuffering_CanonicalUsecase() { - const string Category = "B1"; - var clock = new FakeTimeProvider(TimeProvider.System.GetUtcNow()); - - GlobalBufferOptions options = new() - { - Duration = TimeSpan.FromSeconds(60), - SuspendAfterFlushDuration = TimeSpan.FromSeconds(0), - Rules = new List - { - new(null, LogLevel.Warning, null), - } - }; - using var buffer = new GlobalBuffer(new StaticOptionsMonitor(options), clock); - using var provider = new Provider(); using var factory = Utils.CreateLoggerFactory( builder => { builder.AddProvider(provider); - builder.Services.AddSingleton(buffer); - builder.AddGlobalBufferProvider(); + builder.AddGlobalBuffer(LogLevel.Warning); }); - var logger = factory.CreateLogger(Category); + var 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 is not flushed + // nothing is logged because the buffer not flushed yet Assert.Equal(0, provider.Logger!.Collector.Count); - buffer.Flush(); - - // 2 log records emitted because the buffer was flushed - Assert.Equal(2, provider.Logger!.Collector.Count); - - logger.LogWarning("MSG0"); - logger.Log(LogLevel.Warning, new EventId(2, "ID2"), "some state", null, (_, _) => "MSG2"); - - clock.Advance(options.Duration); + // instead of this, users would get IBufferManager from DI and call Flush on it + var dlf = (Utils.DisposingLoggerFactory)factory; + var bufferManager = dlf.ServiceProvider.GetRequiredService(); - // forcefully clear buffer instead of async waiting for it to be done on its own which is inherently racy. - buffer.RemoveExpiredItems(); + bufferManager.Flush(); - // still 2 because the buffer is cleared after Duration time elapses + // 2 log records emitted because the buffer has been flushed Assert.Equal(2, provider.Logger!.Collector.Count); } #endif diff --git a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/Utils.cs b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/Utils.cs index bf09f8cb91c..cb6a39a29e8 100644 --- a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/Utils.cs +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/Utils.cs @@ -24,21 +24,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 readonly ServiceProvider ServiceProvider; 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/Microsoft.Extensions.Telemetry.Tests.csproj b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Microsoft.Extensions.Telemetry.Tests.csproj index 686a095d822..7273b05c6c7 100644 --- a/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Microsoft.Extensions.Telemetry.Tests.csproj +++ b/test/Libraries/Microsoft.Extensions.Telemetry.Tests/Microsoft.Extensions.Telemetry.Tests.csproj @@ -20,7 +20,6 @@ -