Add logging buffering #5635
Add logging buffering #5635
Conversation
| if (loggerInfo.Logger is IBufferedLogger bufferedLogger) | ||
| { | ||
| if (config.BufferProvider is not null && | ||
| config.BufferProvider.CurrentBuffer.TryEnqueue(bufferedLogger, logLevel, loggerInfo.Category!, eventId, joiner, exception, joiner.Formatter!(joiner.State, exception))) |
There was a problem hiding this comment.
I think we'd want to only buffer the log data once even if there are multiple LogProviders that will ultimately receive it. Otherwise we might be duplicating large amounts of data for little benefit.
| if (loggerInfo.Logger is IBufferedLogger bufferedLogger) | ||
| { | ||
| if (config.BufferProvider is not null && | ||
| config.BufferProvider.CurrentBuffer.TryEnqueue(bufferedLogger, logLevel, loggerInfo.Category!, eventId, joiner, exception, joiner.Formatter!(joiner.State, exception))) |
There was a problem hiding this comment.
My previous understanding of our intended policy is that we were going to buffer messages whenever buffering was enabled, regardless of whether the logger implements IBufferedLogger. When using buffering with an ILogger that doesn't support buffered logging we would just invoke the ILogger.Log() method and accept that the behavior might be sub-optimal if the logger captured new timestamps, thread ids or other ambient state.
If folks want to change that policy to something else I'm happy to discuss it, but otherwise I'd suggest we stick to buffering regardless of whether IBufferLogger is implemented.
| { | ||
| // 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. |
There was a problem hiding this comment.
The set of logger providers can change dynamically as the program runs which means LoggerProviders at the time the time a buffer is flushed might not be the same as the LoggerProviders which were present when a given message was enqueued. I suspect users would find the behavior more intuitive if we flush using whatever providers are active at the time the flush occurs rather than cached providers from earlier in the program's execution. One way to achieve could be to have ExtendedLogger create an instance of IBufferedLogger which when invoked enumerates all current providers and forwards the call.
| ? _globalBufferProvider.CurrentBuffer | ||
| : _requestBuffers.GetOrAdd(_accessor.HttpContext.TraceIdentifier, _accessor.HttpContext.RequestServices.GetRequiredService<HttpRequestBuffer>()); | ||
|
|
||
| // TO DO: Dispose request buffer when the respective HttpContext is disposed |
There was a problem hiding this comment.
I assume you mean you want to get the HttpRequestBuffer out of the dictionary? What might be easier is to avoid using _requestBuffers at all and instead use a storage location that is already scoped to HttpContext. For example HttpRequest.Items or HttpContext.RequestServices.
| /// <summary> | ||
| /// Gets or sets the size of the buffer for a request. | ||
| /// </summary> | ||
| public int PerRequestCapacity { get; set; } = 1_000; |
There was a problem hiding this comment.
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.
| /// <summary> | ||
| /// Gets or sets the size of the buffer. | ||
| /// </summary> | ||
| public int Capacity { get; set; } = 1_000_000; |
There was a problem hiding this comment.
This seems like a pretty large default size.
| }); | ||
|
|
||
| var serviceProvider = serviceCollection.BuildServiceProvider(); | ||
| var buffer = serviceProvider.GetService<ILoggingBuffer>(); |
There was a problem hiding this comment.
Are we expecting users to query the buffer from the DI container for some reason? I wasn't expecting them to do that. If there was going to be some buffer in the DI container I also would have expected it to be the GlobalBuffer as there is no http request in progress.
| @@ -714,6 +718,48 @@ await RunAsync( | |||
| }); | |||
| } | |||
|
|
|||
| #if NET9_0_OR_GREATER | |||
| [Fact] | |||
| public async Task HttpRequestBuffering() | |||
There was a problem hiding this comment.
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.
| }); | ||
|
|
||
| var serviceProvider = serviceCollection.BuildServiceProvider(); | ||
| var buffer = serviceProvider.GetService<ILoggingBuffer>(); |
There was a problem hiding this comment.
I'm not sure we'd want this buffer registered under a public interface in DI. Is there a user-scenario where it matters?
| @@ -119,6 +122,58 @@ public static void FeatureEnablement(bool enableRedaction, bool enableEnrichment | |||
| } | |||
| } | |||
|
|
|||
| #if NET9_0_OR_GREATER | |||
| [Fact] | |||
| public static void GlobalBuffering() | |||
There was a problem hiding this comment.
Similar to Http, it would be nice to have an example that uses global buffering in some canonical way that we expect end-users to use it.
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