Add logging buffering #5635

evgenyfedorov2 · 2024-11-13T15:09:37Z

Related to the #5123 proposal, this PR is focused on the logging buffering only. See also the sampling part #5574.

Microsoft Reviewers: Open in CodeFlow

src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs

...Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferProvider.cs

noahfalk · 2024-11-23T00:44:52Z

src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferOptions.cs

+    /// <summary>
+    /// Gets or sets the size of the buffer for a request.
+    /// </summary>
+    public int PerRequestCapacity { get; set; } = 1_000;


Is this measured in log messages? I think we should also consider if we need guards on the size of an individual message or size of all messages combined. For example if someone logged 500 messages each of size 10MB I expect many services would fail with an OOM. I don't expect anyone would intentionally log such a large message but it might happen because of an unintended bug or a malicious actor has discovered a way to get large content into a log message.

Yes, it is in log messages. I don't know yet how to make performant memory size limit for that, but I will keep this thread open to get back to it later.

Shouldn't this be a total size of the underlying buffer? "Don't buffer more than N bytes"?

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs

...Core.Diagnostics.Middleware.Tests/Buffering/HttpRequestBufferLoggerBuilderExtensionsTests.cs

noahfalk · 2024-11-23T08:45:33Z

test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/AcceptanceTests.cs

@@ -714,6 +718,48 @@ await RunAsync(
            });
    }

+#if NET9_0_OR_GREATER
+    [Fact]
+    public async Task HttpRequestBuffering()


It doesn't have to be this test, but it would be nice to have some test or sample code that uses the feature the way we expect an end-user to use it. For example I would not expect end users to new up the Options type, create their own instances of HttpRequestBuffer or manually add objects to the DI container.

Updated this test, users (as of today) are supposed to inject IHttpRequestBufferManager into their middleware and call Flush() and/or FlushCurrentRequestLogs() on it

...s/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferLoggerBuilderExtensionsTests.cs

test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs

geeknoid · 2024-12-15T20:56:22Z

...Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IHttpRequestBufferManager.cs

+/// Interface for a HTTP request buffer manager.
+/// </summary>
+[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)]
+public interface IHttpRequestBufferManager : IBufferManager


Could this type be internal?

Users will use buffering either via this interface (for HTTP or non-HTTP request logs or for both) or via IBufferManager(for non-HTTP request logs only) injected via constructor, that's why it should be public.

geeknoid · 2024-12-15T20:58:53Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferFilterRule.cs

+/// Defines a rule used to filter log messages for purposes of futher buffering.
+/// </summary>
+[Experimental(diagnosticId: DiagnosticIds.Experiments.Telemetry, UrlFormat = DiagnosticIds.UrlFormat)]
+public class BufferFilterRule : ILoggerFilterRule


I think we need to also support filtering per name/value pair. So that you can control buffering based on things like cluster name or region.

...soft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferLoggerBuilderExtensions.cs

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs

geeknoid · 2024-12-15T21:03:38Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs

+    public TimeSpan Duration { get; set; } = TimeSpan.FromSeconds(30);
+
+    /// <summary>
+    /// Gets or sets the size of the buffer.


Is this in log records? If so, I think this should be expressed in bytes, since the total size of individual log records may vary wildly.

KalleOlaviNiemitalo · 2024-12-16T09:13:43Z

src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferManager.cs

+        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}");
+        }


I wonder if the key in HttpContext.Items should be something more complex than just string category, in case a library is already using the same string as a log category name and as a key in HttpContext.Items, and an application that uses this library is being changed to use log buffering.

Another risk here is that HttpContext is not thread-safe. If the request causes asynchronous work on multiple threads, and those threads log events in parallel (with the same log category or different categories), then the HttpContext.Items dictionary could be corrupted. Not sure how to fix this.

Address PR comments Add .NET 8 support Add ExceptionJsonConverter

dotnet-comment-bot · 2024-12-16T15:24:35Z

‼️ Found issues ‼️

Project	Coverage Type	Expected	Actual
Microsoft.AspNetCore.Diagnostics.Middleware	Line	100	96.03 🔻
Microsoft.AspNetCore.Diagnostics.Middleware	Branch	100	98.51 🔻
Microsoft.Extensions.Telemetry	Line	93	86.2 🔻
Microsoft.Extensions.Telemetry	Branch	93	84.59 🔻
Microsoft.Extensions.Diagnostics.Testing	Line	99	85.78 🔻
Microsoft.Extensions.Diagnostics.Testing	Branch	99	79.57 🔻

🎉 Good job! The coverage increased 🎉
Update MinCodeCoverage in the project files.

Project	Expected	Actual
Microsoft.Extensions.Diagnostics.Probes	70	76
Microsoft.Extensions.Caching.Hybrid	75	86
Microsoft.Extensions.AI.OpenAI	72	77

Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=896358&view=codecoverage-tab

KalleOlaviNiemitalo · 2024-12-17T08:35:21Z

src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs

-// NOTE: This implementation uses thread local storage. As a result, it will fail if formatter code, enricher code, or
+// NOTE: This implementation uses thread local storage. As a wasBuffered, it will fail if formatter code, enricher code, or


That change looks unintended.

KalleOlaviNiemitalo · 2024-12-17T11:40:59Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs

+        {
+            case ModernTagJoiner modernTagJoiner:
+                _buffer.Enqueue(new SerializedLogRecord(logLevel, eventId, _timeProvider.GetUtcNow(), modernTagJoiner, exception,
+                    ((Func<ModernTagJoiner, Exception?, string>)(object)formatter)(modernTagJoiner, exception)));


Is this casting more performant than just formatter(attributes, exception)?

KalleOlaviNiemitalo · 2024-12-17T11:45:00Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBuffer.cs

+internal interface ILoggingBuffer
+{
+    /// <summary>
+    /// Enqueues a log record in the underlying buffer..


Double dot. But I'm not sure whether internal interfaces should even have XML documentation comments.

KalleOlaviNiemitalo · 2024-12-17T11:48:49Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs

+    public void Flush()
+    {
+        var result = _buffer.ToArray();
+
+#if NETFRAMEWORK
+        lock (_netfxBufferLocker)
+        {
+            while (_buffer.TryDequeue(out _))
+            {
+                // Clear the buffer
+            }
+        }
+#else
+        _buffer.Clear();
+#endif


This loses log entries if another thread enqueues more of them between _buffer.ToArray() and _buffer.Clear(). That is more likely to happen on .NET Framework, where clearing the queue takes more time.

KalleOlaviNiemitalo · 2024-12-17T12:01:22Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferManager.cs

+    {
+        while (!cancellationToken.IsCancellationRequested)
+        {
+            await _timeProvider.Delay(_options.CurrentValue.Duration, cancellationToken).ConfigureAwait(false);


IIRC, IOptionsMonitor<TOptions>.CurrentValue throws if the option is bound to configuration and the binding fails (parsing fails or a validator rejects the value); this could even happen when an operator modifies a configuration file after the application has already started. The BackgroundService would then fail and, depending on HostOptions.BackgroundServiceExceptionBehavior, either log buffer truncation would stop working or the whole application would terminate. Should this instead keep using the previous value of the options in that case?

KalleOlaviNiemitalo · 2024-12-17T12:07:19Z

src/Libraries/Microsoft.Extensions.Telemetry/ILoggerFilterRule.cs

+/// <summary>
+/// Represents a rule used for filtering log messages for purposes of log sampling and buffering.
+/// </summary>
+internal interface ILoggerFilterRule


The ILoggerFilterRule interface doesn't look useful when it is internal and has only one implementation and has only read-only properties (rather than a method that checks whether the rule is applicable). LoggerFilterRuleSelector could instead use the BufferFilterRule class directly.

KalleOlaviNiemitalo · 2024-12-17T16:13:44Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferSink.cs

+                        logger.Log(
+                            serializedRecord.LogLevel,
+                            serializedRecord.EventId,
+                            serializedRecord.Attributes,
+                            exception,
+                            (_, _) => serializedRecord.FormattedMessage ?? string.Empty);


This allocates a closure and a delegate for each ILogger.Log<TState> call. I can think of two ways to minimize the allocations:

Instead of serializedRecord.Attributes, pass serializedRecord itself as the state to ILogger.Log<TState>. Implement IReadOnlyList<KeyValuePair<string, object?>> in SerializedLogRecord by calling the corresponding methods of public IReadOnlyList<KeyValuePair<string, string>> Attributes.

Alternatively, keep using the same delegate across all iterations of both foreach loops; declare the serializedRecord variable and a delegate variable before the outer loop. That way, it would allocate only one closure and one delegate per BufferSink.LogRecords call, no matter how many log records are in IEnumerable<T> serializedRecords. This is safe because ILogger.Log<TState> is not allowed to save the formatter delegate for later calling.

KalleOlaviNiemitalo · 2024-12-17T16:30:35Z

src/Shared/ExceptionJsonConverter/ExceptionJsonConverter.cs

+        }
+        else
+        {
+            exception = Activator.CreateInstance(deserializedType, message) as Exception;


This will pass the wrong argument to ArgumentNullException(string? paramName).

KalleOlaviNiemitalo · 2024-12-17T16:34:41Z

src/Shared/ExceptionJsonConverter/ExceptionJsonConverter.cs

+                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;


What's the recovery plan if the exception type has no suitable constructor and Activator.CreateInstance throws MethodInvocationException? For example, System.ServiceModel.FaultException<TDetail> does not have any constructors that take just (String) or (String, Exception).

This reconstruction of exception instances from JSON would not be necessary if loggers that do not implement IBufferedLogger were given the log entries immediately without buffering.

KalleOlaviNiemitalo · 2024-12-18T10:14:54Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/PooledLogRecord.cs

+using Microsoft.Extensions.ObjectPool;
+
+namespace Microsoft.Extensions.Diagnostics.Buffering;
+internal sealed class PooledLogRecord : BufferedLogRecord, IResettable


Please add DebuggerDisplayAttribute so that the list of log records in a buffer can be viewed more easily.

KalleOlaviNiemitalo · 2024-12-18T10:22:06Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/PooledLogRecord.cs

+    public override IReadOnlyList<KeyValuePair<string, object?>> Attributes => _attributes;
+    private IReadOnlyList<KeyValuePair<string, object?>> _attributes;
+
+    public bool TryReset()


What calls PooledLogRecord.TryReset()? BufferSink does PoolFactory.CreateListPool<PooledLogRecord>() and _logRecordPool.Return(pooledList), but PooledListPolicy<T>.Return(List<T>) clears only the list itself and does not call IResettable.Reset() on the elements of the list.

KalleOlaviNiemitalo · 2024-12-20T19:05:05Z

src/Libraries/Microsoft.Extensions.Telemetry/ILoggerFilterRule.cs

+    /// <summary>
+    /// Gets the maximum <see cref="LogLevel"/> of messages where this rule applies to.
+    /// </summary>
+    public int? EventId { get; }


Wrong documentation.

KalleOlaviNiemitalo · 2024-12-21T01:34:00Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/PooledLogRecord.cs

+    public override string? MessageTemplate => _messageTemplate;
+    private string? _messageTemplate;


PooledLogRecord._messageTemplate is always null. Only PooledLogRecord.TryReset writes to it.

KalleOlaviNiemitalo · 2024-12-21T01:35:02Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferSink.cs

+                            pooledList.Add(
+                                new PooledLogRecord(
+                                    serializedRecord.Timestamp,
+                                    serializedRecord.LogLevel,
+                                    serializedRecord.EventId,
+                                    serializedRecord.Exception,
+                                    serializedRecord.FormattedMessage,
+                                    serializedRecord.Attributes.Select(kvp => new KeyValuePair<string, object?>(kvp.Key, kvp.Value)).ToArray()));


These PooledLogRecord instances should presumably be rented from a pool but that has not been implemented; only the List<PooledLogRecord> instances are pooled, not the records themselves.

If the record were pooled, then it might be useful to pool the PooledLogRecord.Attributes arrays too. For that, there are a few options:

Change the type of PooledLogRecord._attributes to List<KeyValuePair<string, object>>. When the PooledLogRecord instance is returned to the pool, keep the attribute list attached; when the instance is rented again from the pool, reuse the attribute list and resize it if necessary.

Con: If most log entries have no attributes, but some rare log entries have hundreds of attributes, then over time most PooledLogRecord instances in the pool would get their attribute lists expanded to the largest size, wasting memory.

When the PooledLogRecord instance is returned to the pool, detach the attribute array and pool it separately in an ArrayPool<KeyValuePair<string, object>>.

Pro: Separate buckets for different array sizes.

Con: Because ArrayPool<T>.Rent can return a larger array than requested, PooledLogRecord.Attributes would have to return a size-limiting wrapper rather than the array itself. ArraySegment<T> implements IReadOnlyList<T> but it would have to be boxed anew each time the backing array is replaced. A custom class that implements IReadOnlyList<T> and allows reinitializing with a different array should work but I'm not sure about the performance.

KalleOlaviNiemitalo · 2024-12-21T01:41:34Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/SerializedLogRecord.cs

+#if NETFRAMEWORK
+            serializedAttributes.Add(new KeyValuePair<string, string>(new string(attributes[i].Key.ToCharArray()), attributes[i].Value?.ToString() ?? string.Empty));
+#else
+            serializedAttributes.Add(new KeyValuePair<string, string>(new string(attributes[i].Key), attributes[i].Value?.ToString() ?? string.Empty));
+#endif


Why does this copy the attribute key strings -- is that related to collectible assembly load contexts?

KalleOlaviNiemitalo · 2024-12-21T01:42:58Z

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/PooledLogRecord.cs

+    public override IReadOnlyList<KeyValuePair<string, object?>> Attributes => _attributes;
+    private IReadOnlyList<KeyValuePair<string, object?>> _attributes;


Is BufferedLogRecord.Attributes expected to include the "{OriginalFormat}" entry whose value should be in BufferedLogRecord.MessageTemplate too?

KalleOlaviNiemitalo · 2024-12-21T01:47:40Z

src/Libraries/Microsoft.Extensions.Telemetry/LoggerFilterRuleSelector.cs

+            if (!category.AsSpan().StartsWith(prefix, StringComparison.OrdinalIgnoreCase) ||
+                !category.AsSpan().EndsWith(suffix, StringComparison.OrdinalIgnoreCase))
+            {
+                return false;


A length check seems to be missing. Consider rule.Category = "abb*bbc", which causes prefix = "abb" and suffix = "bbc". Then if category = "abbc", it should not match because it is too short, but this code accepts it because it starts with "abb" and ends with "bbc".

Filed dotnet/runtime#110890 for a similar bug in Microsoft.Extensions.Logging.LoggerRuleSelector.

KalleOlaviNiemitalo · 2024-12-21T01:55:17Z

src/Libraries/Microsoft.Extensions.Telemetry/LoggerFilterRuleSelector.cs

+                if (wildcardIndex != -1 &&
+                    categoryName.IndexOf(WildcardChar, wildcardIndex + 1) != -1)
+                {
+                    throw new InvalidOperationException("Only one wildcard character is allowed in category name.");


If this error were thrown from IValidateOptions<GlobalBufferOptions> and IValidateOptions<HttpRequestBufferOptions>, the error might be easier to handle there, especially during configuration reload.

Buffering

988c709

dotnet-policy-service bot assigned evgenyfedorov2 Nov 13, 2024

noahfalk reviewed Nov 23, 2024

View reviewed changes

evgenyfedorov2 force-pushed the evgenyfedorov2/log_buffering branch 2 times, most recently from e40b7b6 to 9d61d12 Compare December 12, 2024 16:30

Major update

2f1a335

evgenyfedorov2 force-pushed the evgenyfedorov2/log_buffering branch from 9d61d12 to 2f1a335 Compare December 12, 2024 17:36

Remove Json exception converter

2d2412e

geeknoid reviewed Dec 15, 2024

View reviewed changes

...soft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferLoggerBuilderExtensions.cs Outdated Show resolved Hide resolved

geeknoid reviewed Dec 15, 2024

View reviewed changes

src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs Outdated Show resolved Hide resolved

geeknoid reviewed Dec 15, 2024

View reviewed changes

KalleOlaviNiemitalo reviewed Dec 16, 2024

View reviewed changes

evgenyfedorov2 added 2 commits December 16, 2024 14:32

Fix namespaces

f7eaab1

Address PR comments Add .NET 8 support Add ExceptionJsonConverter

Merge branch 'main' into evgenyfedorov2/log_buffering

1f464df

evgenyfedorov2 force-pushed the evgenyfedorov2/log_buffering branch from 883334d to 022f00c Compare December 16, 2024 14:23

Fix build

a371d9c

evgenyfedorov2 force-pushed the evgenyfedorov2/log_buffering branch from 022f00c to a371d9c Compare December 16, 2024 14:51

KalleOlaviNiemitalo reviewed Dec 17, 2024

View reviewed changes

KalleOlaviNiemitalo reviewed Dec 18, 2024

View reviewed changes

KalleOlaviNiemitalo reviewed Dec 20, 2024

View reviewed changes

KalleOlaviNiemitalo reviewed Dec 21, 2024

View reviewed changes

KalleOlaviNiemitalo mentioned this pull request Dec 22, 2024

LoggerFilterRule.CategoryName matches overlapping prefix and suffix dotnet/runtime#110890

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add logging buffering #5635

Add logging buffering #5635

evgenyfedorov2 commented Nov 13, 2024 •

edited by dotnet-policy-service bot

Loading

noahfalk Nov 23, 2024

evgenyfedorov2 Dec 12, 2024

geeknoid Dec 15, 2024

noahfalk Nov 23, 2024

evgenyfedorov2 Dec 11, 2024 •

edited

Loading

geeknoid Dec 15, 2024

evgenyfedorov2 Dec 16, 2024

geeknoid Dec 15, 2024

geeknoid Dec 15, 2024

KalleOlaviNiemitalo Dec 16, 2024

dotnet-comment-bot commented Dec 16, 2024

KalleOlaviNiemitalo Dec 17, 2024

KalleOlaviNiemitalo Dec 17, 2024

KalleOlaviNiemitalo Dec 17, 2024

KalleOlaviNiemitalo Dec 17, 2024

KalleOlaviNiemitalo Dec 17, 2024

KalleOlaviNiemitalo Dec 17, 2024

KalleOlaviNiemitalo Dec 17, 2024

KalleOlaviNiemitalo Dec 17, 2024

KalleOlaviNiemitalo Dec 17, 2024

KalleOlaviNiemitalo Dec 18, 2024

KalleOlaviNiemitalo Dec 18, 2024

KalleOlaviNiemitalo Dec 18, 2024

KalleOlaviNiemitalo Dec 20, 2024

KalleOlaviNiemitalo Dec 21, 2024

KalleOlaviNiemitalo Dec 21, 2024

KalleOlaviNiemitalo Dec 21, 2024

KalleOlaviNiemitalo Dec 21, 2024

KalleOlaviNiemitalo Dec 21, 2024

KalleOlaviNiemitalo Dec 22, 2024

KalleOlaviNiemitalo Dec 21, 2024

		// NOTE: This implementation uses thread local storage. As a result, it will fail if formatter code, enricher code, or
		// NOTE: This implementation uses thread local storage. As a wasBuffered, it will fail if formatter code, enricher code, or

		public override string? MessageTemplate => _messageTemplate;
		private string? _messageTemplate;

		public override IReadOnlyList<KeyValuePair<string, object?>> Attributes => _attributes;
		private IReadOnlyList<KeyValuePair<string, object?>> _attributes;

Add logging buffering #5635

Are you sure you want to change the base?

Add logging buffering #5635

Conversation

evgenyfedorov2 commented Nov 13, 2024 • edited by dotnet-policy-service bot Loading

Microsoft Reviewers: Open in CodeFlow

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

evgenyfedorov2 Dec 11, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dotnet-comment-bot commented Dec 16, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

evgenyfedorov2 commented Nov 13, 2024 •

edited by dotnet-policy-service bot

Loading

evgenyfedorov2 Dec 11, 2024 •

edited

Loading