Skip to content
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
using System.Linq;
using System.Threading;
using Microsoft.Extensions.Diagnostics.Buffering;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.ObjectPool;
using Microsoft.Extensions.Options;
Expand All @@ -23,6 +24,7 @@ internal sealed class IncomingRequestLogBuffer
PoolFactory.CreateListPoolWithCapacity<DeserializedLogRecord>(MaxBatchSize);

private readonly IBufferedLogger _bufferedLogger;
private readonly IExternalScopeProvider _scopeProvider;
private readonly IOptionsMonitor<PerRequestLogBufferingOptions> _options;
private readonly TimeProvider _timeProvider = TimeProvider.System;
private readonly LogBufferingFilterRule[] _filterRules;
Expand All @@ -35,9 +37,11 @@ internal sealed class IncomingRequestLogBuffer
public IncomingRequestLogBuffer(
IBufferedLogger bufferedLogger,
string category,
IOptionsMonitor<PerRequestLogBufferingOptions> options)
IOptionsMonitor<PerRequestLogBufferingOptions> options,
IExternalScopeProvider scopeProvider)
{
_bufferedLogger = bufferedLogger;
_scopeProvider = scopeProvider;
_options = options;
_filterRules = LogBufferingFilterRuleSelector.SelectByCategory(_options.CurrentValue.Rules.ToArray(), category);
}
Expand Down Expand Up @@ -72,7 +76,8 @@ public bool TryEnqueue<TState>(LogEntry<TState> logEntry)
_timeProvider.GetUtcNow(),
attributes,
logEntry.Exception,
logEntry.Formatter(logEntry.State, logEntry.Exception));
logEntry.Formatter(logEntry.State, logEntry.Exception),
_options.CurrentValue.IncludeScopes ? _scopeProvider : null);

if (serializedLogRecord.SizeInBytes > _options.CurrentValue.MaxLogRecordSizeInBytes)
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,11 @@ public static ILoggingBuilder AddPerIncomingRequestBuffer(this ILoggingBuilder b

return builder
.AddPerRequestBufferManager()
.AddGlobalBuffer(opts => opts.Rules = options.Rules);
.AddGlobalBuffer(opts =>
{
opts.Rules = options.Rules;
opts.IncludeScopes = options.IncludeScopes;
});
}

/// <summary>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
using Microsoft.AspNetCore.Http;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Diagnostics.Buffering;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.Options;

Expand All @@ -16,15 +17,18 @@ internal sealed class PerRequestLogBufferManager : PerRequestLogBuffer

private readonly GlobalLogBuffer _globalBuffer;
private readonly IHttpContextAccessor _httpContextAccessor;
private readonly IExternalScopeProvider _scopeProvider;

public PerRequestLogBufferManager(
GlobalLogBuffer globalBuffer,
IHttpContextAccessor httpContextAccessor,
IOptionsMonitor<PerRequestLogBufferingOptions> options)
IOptionsMonitor<PerRequestLogBufferingOptions> options,
IExternalScopeProvider scopeProvider)
{
_globalBuffer = globalBuffer;
_httpContextAccessor = httpContextAccessor;
Options = options;
_scopeProvider = scopeProvider;
}

public override void Flush()
Expand All @@ -45,7 +49,7 @@ public override bool TryEnqueue<TState>(IBufferedLogger bufferedLogger, in LogEn
IncomingRequestLogBufferHolder? bufferHolder =
httpContext.RequestServices?.GetService<IncomingRequestLogBufferHolder>();
IncomingRequestLogBuffer? buffer = bufferHolder?.GetOrAdd(category, _ =>
new IncomingRequestLogBuffer(bufferedLogger, category, Options));
new IncomingRequestLogBuffer(bufferedLogger, category, Options, _scopeProvider));

if (buffer is null)
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,7 @@ public void Configure(PerRequestLogBufferingOptions options)
options.MaxLogRecordSizeInBytes = parsedOptions.MaxLogRecordSizeInBytes;
options.MaxPerRequestBufferSizeInBytes = parsedOptions.MaxPerRequestBufferSizeInBytes;
options.AutoFlushDuration = parsedOptions.AutoFlushDuration;
options.IncludeScopes = parsedOptions.IncludeScopes;

foreach (LogBufferingFilterRule rule in parsedOptions.Rules)
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -5,8 +5,10 @@
using System;
using System.Collections.Generic;
using System.ComponentModel.DataAnnotations;
using System.Diagnostics.CodeAnalysis;
using Microsoft.Extensions.Diagnostics.Buffering;
using Microsoft.Shared.Data.Validation;
using Microsoft.Shared.DiagnosticIds;

namespace Microsoft.AspNetCore.Diagnostics.Buffering;

Expand Down Expand Up @@ -58,6 +60,16 @@ public class PerRequestLogBufferingOptions
[Range(MinimumPerRequestBufferSizeInBytes, MaximumPerRequestBufferSizeInBytes)]
public int MaxPerRequestBufferSizeInBytes { get; set; } = DefaultPerRequestBufferSizeInBytes;

/// <summary>
/// Gets or sets a value indicating whether logging scopes are added to the attributes of log records when they're buffered.
/// </summary>
/// <remarks>
/// Only scopes that implement <c>IEnumerable&lt;KeyValuePair&lt;string, object?&gt;&gt;</c> are added, without their "{OriginalFormat}" pairs.
/// Scope values are converted to strings and count toward <see cref="MaxLogRecordSizeInBytes"/> and <see cref="MaxPerRequestBufferSizeInBytes"/>.
/// </remarks>
[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)]
public bool IncludeScopes { get; set; }

/// <summary>
/// Gets or sets the collection of <see cref="LogBufferingFilterRule"/> used for filtering log messages for the purpose of further buffering.
/// </summary>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -184,6 +184,10 @@
"Member": "System.TimeSpan Microsoft.AspNetCore.Diagnostics.Buffering.PerRequestLogBufferingOptions.AutoFlushDuration { get; set; }",
"Stage": "Stable"
},
{
"Member": "bool Microsoft.AspNetCore.Diagnostics.Buffering.PerRequestLogBufferingOptions.IncludeScopes { get; set; }",
"Stage": "Experimental"
},
{
"Member": "int Microsoft.AspNetCore.Diagnostics.Buffering.PerRequestLogBufferingOptions.MaxLogRecordSizeInBytes { get; set; }",
"Stage": "Stable"
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -74,6 +74,8 @@ public class MyService
Per-request buffering is especially useful for capturing all logs related to a specific HTTP request and making decisions about them collectively based on request outcomes.
Per-request buffering is tightly coupled with [Global Buffering](https://github.com/dotnet/extensions/blob/main/src/Libraries/Microsoft.Extensions.Telemetry/README.md#log-buffering). If a log entry is supposed to be buffered to a per-request buffer, but there is no active HTTP context, it will be buffered to the global buffer instead. If buffer flush is triggered, the per-request buffer will be flushed first, followed by the global buffer.

To preserve logging scopes in buffered log records, set the experimental `IncludeScopes` option, which adds the scopes' name/value pairs to the records' attributes.

### Tracking HTTP Request Latency

These components enable tracking and reporting the latency of HTTP request processing.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
using System.Collections.Generic;
using System.Linq;
using System.Threading;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.ObjectPool;
using Microsoft.Extensions.Options;
Expand All @@ -25,6 +26,7 @@ internal sealed class GlobalBuffer : IDisposable

private readonly IOptionsMonitor<GlobalLogBufferingOptions> _options;
private readonly IBufferedLogger _bufferedLogger;
private readonly IExternalScopeProvider _scopeProvider;
private readonly TimeProvider _timeProvider;
private readonly IDisposable? _optionsChangeTokenRegistration;
private readonly string _category;
Expand All @@ -42,11 +44,13 @@ public GlobalBuffer(
IBufferedLogger bufferedLogger,
string category,
IOptionsMonitor<GlobalLogBufferingOptions> options,
TimeProvider timeProvider)
TimeProvider timeProvider,
IExternalScopeProvider scopeProvider)
{
_options = Throw.IfNull(options);
_timeProvider = timeProvider;
_bufferedLogger = bufferedLogger;
_scopeProvider = scopeProvider;
_category = Throw.IfNullOrEmpty(category);
LastKnownGoodFilterRules = LogBufferingFilterRuleSelector.SelectByCategory(_options.CurrentValue.Rules.ToArray(), _category);
_optionsChangeTokenRegistration = options.OnChange(OnOptionsChanged);
Expand Down Expand Up @@ -94,7 +98,8 @@ public bool TryEnqueue<TState>(LogEntry<TState> logEntry)
_timeProvider.GetUtcNow(),
attributes,
logEntry.Exception,
logEntry.Formatter(logEntry.State, logEntry.Exception));
logEntry.Formatter(logEntry.State, logEntry.Exception),
_options.CurrentValue.IncludeScopes ? _scopeProvider : null);

if (serializedLogRecord.SizeInBytes > _options.CurrentValue.MaxLogRecordSizeInBytes)
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -92,6 +92,9 @@ private static ILoggingBuilder AddGlobalBufferManager(this ILoggingBuilder build
{
_ = builder.Services.AddExtendedLoggerFeactory();

builder.Services.TryAddSingleton<IExternalScopeProvider>(static sp =>
new LoggerFactoryScopeProvider(sp.GetRequiredService<IOptions<LoggerFactoryOptions>>().Value.ActivityTrackingOptions));

builder.Services.TryAddSingleton<GlobalLogBufferManager>();
builder.Services.TryAddSingleton<GlobalLogBuffer>(static sp => sp.GetRequiredService<GlobalLogBufferManager>());
builder.Services.TryAddSingleton<LogBuffer>(static sp => sp.GetRequiredService<GlobalLogBufferManager>());
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@

using System;
using System.Collections.Concurrent;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.Options;

Expand All @@ -14,18 +15,21 @@ internal sealed class GlobalLogBufferManager : GlobalLogBuffer
internal readonly ConcurrentDictionary<string, GlobalBuffer> Buffers = [];
private readonly IOptionsMonitor<GlobalLogBufferingOptions> _options;
private readonly TimeProvider _timeProvider;
private readonly IExternalScopeProvider _scopeProvider;

public GlobalLogBufferManager(IOptionsMonitor<GlobalLogBufferingOptions> options)
: this(options, TimeProvider.System)
public GlobalLogBufferManager(IOptionsMonitor<GlobalLogBufferingOptions> options, IExternalScopeProvider scopeProvider)
: this(options, TimeProvider.System, scopeProvider)
{
}

internal GlobalLogBufferManager(
IOptionsMonitor<GlobalLogBufferingOptions> options,
TimeProvider timeProvider)
TimeProvider timeProvider,
IExternalScopeProvider scopeProvider)
{
_options = options;
_timeProvider = timeProvider;
_scopeProvider = scopeProvider;
}

public override void Flush()
Expand All @@ -44,14 +48,16 @@ public override bool TryEnqueue<TState>(IBufferedLogger bufferedLogger, in LogEn
state.bufferedLogger,
category,
state._options,
state._timeProvider),
(bufferedLogger, _options, _timeProvider));
state._timeProvider,
state._scopeProvider),
(bufferedLogger, _options, _timeProvider, _scopeProvider));
#else
GlobalBuffer buffer = Buffers.GetOrAdd(category, category => new GlobalBuffer(
bufferedLogger,
category,
_options,
_timeProvider));
_timeProvider,
_scopeProvider));
#endif
return buffer.TryEnqueue(logEntry);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,7 @@ public void Configure(GlobalLogBufferingOptions options)
options.MaxLogRecordSizeInBytes = parsedOptions.MaxLogRecordSizeInBytes;
options.MaxBufferSizeInBytes = parsedOptions.MaxBufferSizeInBytes;
options.AutoFlushDuration = parsedOptions.AutoFlushDuration;
options.IncludeScopes = parsedOptions.IncludeScopes;

foreach (LogBufferingFilterRule rule in parsedOptions.Rules)
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,9 @@
using System;
using System.Collections.Generic;
using System.ComponentModel.DataAnnotations;
using System.Diagnostics.CodeAnalysis;
using Microsoft.Shared.Data.Validation;
using Microsoft.Shared.DiagnosticIds;

namespace Microsoft.Extensions.Diagnostics.Buffering;

Expand Down Expand Up @@ -57,6 +59,16 @@ public class GlobalLogBufferingOptions
[Range(MinimumBufferSizeInBytes, MaximumBufferSizeInBytes)]
public int MaxBufferSizeInBytes { get; set; } = DefaultMaxBufferSizeInBytes;

/// <summary>
/// Gets or sets a value indicating whether logging scopes are added to the attributes of log records when they're buffered.
/// </summary>
/// <remarks>
/// Only scopes that implement <c>IEnumerable&lt;KeyValuePair&lt;string, object?&gt;&gt;</c> are added, without their "{OriginalFormat}" pairs.
/// Scope values are converted to strings and count toward <see cref="MaxLogRecordSizeInBytes"/> and <see cref="MaxBufferSizeInBytes"/>.
/// </remarks>
[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)]
public bool IncludeScopes { get; set; }

/// <summary>
/// Gets or sets the collection of <see cref="LogBufferingFilterRule"/> used for filtering log messages for the purpose of further buffering.
/// </summary>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -123,6 +123,10 @@
"Member": "System.TimeSpan Microsoft.Extensions.Diagnostics.Buffering.GlobalLogBufferingOptions.AutoFlushDuration { get; set; }",
"Stage": "Stable"
},
{
"Member": "bool Microsoft.Extensions.Diagnostics.Buffering.GlobalLogBufferingOptions.IncludeScopes { get; set; }",
"Stage": "Experimental"
},
{
"Member": "int Microsoft.Extensions.Diagnostics.Buffering.GlobalLogBufferingOptions.MaxBufferSizeInBytes { get; set; }",
"Stage": "Stable"
Expand Down
4 changes: 3 additions & 1 deletion src/Libraries/Microsoft.Extensions.Telemetry/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -113,11 +113,13 @@ public class MyService

The Global Log Buffer supports the `IOptionsMonitor<T>` pattern, allowing for dynamic configuration updates. This means you can change the buffering rules at runtime without needing to restart your application.

To preserve logging scopes in buffered log records, set the experimental `IncludeScopes` option, which adds the scopes' name/value pairs to the records' attributes.

#### Limitations

1. This library does not preserve the order of log records. However, original timestamps are preserved.
1. The library does not support custom configuration per each logger provider. Same configuration is applied to all logger providers.
1. Log scopes are not supported. This means that if you use `ILogger.BeginScope()` method, the buffered log records will not be associated with the scope.
1. Log scopes are only preserved if the `IncludeScopes` option is enabled, and then only as attributes of buffered log records.
1. When buffering and then flushing buffers, not all information of the original log record is preserved. This is due to serializing/deserializing limitation, but can be
revisited in future. Namely, this library uses `Microsoft.Extensions.Logging.Abstractions.BufferedLogRecord` class when converting buffered log records to actual log records, but omits following properties:

Expand Down
61 changes: 60 additions & 1 deletion src/Shared/LogBuffering/SerializedLogRecordFactory.cs
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,8 @@ namespace Microsoft.Extensions.Diagnostics.Buffering;

internal static class SerializedLogRecordFactory
{
private const string OriginalFormat = "{OriginalFormat}";

private static readonly ObjectPool<List<KeyValuePair<string, object?>>> _attributesPool =
PoolFactory.CreateListPool<KeyValuePair<string, object?>>();

Expand All @@ -23,7 +25,8 @@ public static SerializedLogRecord Create(
DateTimeOffset timestamp,
IReadOnlyList<KeyValuePair<string, object?>> attributes,
Exception? exception,
string formattedMessage)
string formattedMessage,
IExternalScopeProvider? scopeProvider)
{
int sizeInBytes = _serializedLogRecordSize;
List<KeyValuePair<string, object?>> serializedAttributes = _attributesPool.Get();
Expand All @@ -40,6 +43,11 @@ public static SerializedLogRecord Create(
serializedAttributes.Add(new KeyValuePair<string, object?>(key, value));
}

if (scopeProvider is not null)
{
sizeInBytes += AddScopes(serializedAttributes, scopeProvider);
}

string exceptionMessage = string.Empty;
if (exception is not null)
{
Expand All @@ -64,6 +72,57 @@ public static void Return(SerializedLogRecord bufferedRecord)
_attributesPool.Return(bufferedRecord.Attributes);
}

/// <summary>
/// Adds the name/value pairs of the current scopes to the attributes of a log record.
/// </summary>
/// <returns>The approximate size in bytes of the added values.</returns>
private static int AddScopes(List<KeyValuePair<string, object?>> serializedAttributes, IExternalScopeProvider scopeProvider)
{
int count = serializedAttributes.Count;
scopeProvider.ForEachScope(static (scope, attributes) =>
{
if (scope is IReadOnlyList<KeyValuePair<string, object?>> list)
{
for (int i = 0; i < list.Count; i++)
{
AddScopeItem(attributes, list[i]);
}
}
else if (scope is IEnumerable<KeyValuePair<string, object?>> items)
{
foreach (KeyValuePair<string, object?> item in items)
{
AddScopeItem(attributes, item);
}
}
}, serializedAttributes);

int sizeInBytes = 0;
for (int i = count; i < serializedAttributes.Count; i++)
{
sizeInBytes += CalculateStringSize((string)serializedAttributes[i].Value!);
}

// "{OriginalFormat}" needs to stay the last attribute.
if (count > 0 && serializedAttributes[count - 1].Key == OriginalFormat)
{
KeyValuePair<string, object?> originalFormat = serializedAttributes[count - 1];
serializedAttributes.RemoveAt(count - 1);
serializedAttributes.Add(originalFormat);
}

return sizeInBytes;
}

private static void AddScopeItem(List<KeyValuePair<string, object?>> attributes, KeyValuePair<string, object?> item)
{
// Skips the scope's {OriginalFormat} in favor of the log record's own {OriginalFormat}.
if (item.Key != OriginalFormat)
{
attributes.Add(new KeyValuePair<string, object?>(item.Key, item.Value?.ToString() ?? string.Empty));
}
}

private static int CalculateStringSize(string str)
{
if (string.IsNullOrEmpty(str))
Expand Down
Loading
Loading