-
Notifications
You must be signed in to change notification settings - Fork 764
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Add logging buffering #5635
base: main
Are you sure you want to change the base?
Add logging buffering #5635
Conversation
src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs
Outdated
Show resolved
Hide resolved
...Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferProvider.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferOptions.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs
Outdated
Show resolved
Hide resolved
...Core.Diagnostics.Middleware.Tests/Buffering/HttpRequestBufferLoggerBuilderExtensionsTests.cs
Outdated
Show resolved
Hide resolved
test/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware.Tests/Logging/AcceptanceTests.cs
Show resolved
Hide resolved
...s/Microsoft.Extensions.Telemetry.Tests/Buffering/GlobalBufferLoggerBuilderExtensionsTests.cs
Outdated
Show resolved
Hide resolved
test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs
Outdated
Show resolved
Hide resolved
e40b7b6
to
9d61d12
Compare
9d61d12
to
2f1a335
Compare
...Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IHttpRequestBufferManager.cs
Show resolved
Hide resolved
/// 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 |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Would cluster name and region be key-value pairs that are varying within the same process? Based on the names those sound like properties that would be fixed at process startup and remain constant throughout. This means all the decision making could occur at startup time when defining the filter rules rather than a decision that needs to be made per-log message later on. For example could you satisfy the scenario with some startup code like this?
logging.AddBuffering(buffering =>
{
string region = GetRegionFromConfig();
// in the test region we want to buffer some log messages that won't be buffered
// in other regions
if(region == "TestRegion")
{
buffer.AddFilter("ExperimentalFeatures");
}
...
});
I'm not opposed to other things, I'm just trying to better understand what the scenario is.
...soft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferLoggerBuilderExtensions.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferOptions.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferManager.cs
Outdated
Show resolved
Hide resolved
Address PR comments Add .NET 8 support Add ExceptionJsonConverter
883334d
to
022f00c
Compare
022f00c
to
a371d9c
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=896358&view=codecoverage-tab |
src/Libraries/Microsoft.Extensions.Telemetry/Logging/ExtendedLogger.cs
Outdated
Show resolved
Hide resolved
{ | ||
case ModernTagJoiner modernTagJoiner: | ||
_buffer.Enqueue(new SerializedLogRecord(logLevel, eventId, _timeProvider.GetUtcNow(), modernTagJoiner, exception, | ||
((Func<ModernTagJoiner, Exception?, string>)(object)formatter)(modernTagJoiner, exception))); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Is this casting more performant than just formatter(attributes, exception)
?
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBuffer.cs
Outdated
Show resolved
Hide resolved
public void Flush() | ||
{ | ||
var result = _buffer.ToArray(); | ||
|
||
#if NETFRAMEWORK | ||
lock (_netfxBufferLocker) | ||
{ | ||
while (_buffer.TryDequeue(out _)) | ||
{ | ||
// Clear the buffer | ||
} | ||
} | ||
#else | ||
_buffer.Clear(); | ||
#endif |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Moved the _lastFlushTimestamp
update to the top, so that when a flush operation is initiated at one thread, another thread will skip buffering for some period of time because of the non-zero value of SuspendAfterFlushDuration
option. Don't expect someone to set it to zero because it does not make sense to emit some buffered logs and buffer other at almost the same time.
{ | ||
while (!cancellationToken.IsCancellationRequested) | ||
{ | ||
await _timeProvider.Delay(_options.CurrentValue.Duration, cancellationToken).ConfigureAwait(false); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This makes sense, but I will take another look at it later on, possibly after finalizing public API. Keeping this open until then
src/Libraries/Microsoft.Extensions.Telemetry/ILoggerFilterRule.cs
Outdated
Show resolved
Hide resolved
logger.Log( | ||
serializedRecord.LogLevel, | ||
serializedRecord.EventId, | ||
serializedRecord.Attributes, | ||
exception, | ||
(_, _) => serializedRecord.FormattedMessage ?? string.Empty); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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
, passserializedRecord
itself as the state to ILogger.Log<TState>. ImplementIReadOnlyList<KeyValuePair<string, object?>>
in SerializedLogRecord by calling the corresponding methods ofpublic IReadOnlyList<KeyValuePair<string, string>> Attributes
. - Alternatively, keep using the same delegate across all iterations of both
foreach
loops; declare theserializedRecord
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 inIEnumerable<T> serializedRecords
. This is safe because ILogger.Log<TState> is not allowed to save the formatter delegate for later calling.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
makes sense for optimizations later, thank you
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This code moved from BufferSink to BufferedLoggerProxy in d7661a6. The BufferedLogRecord instances are not pooled, so each BufferedLogRecord call costs at least one allocation per BufferedLogRecord; that may make the delegate and closure allocations less important.
using Microsoft.Extensions.ObjectPool; | ||
|
||
namespace Microsoft.Extensions.Diagnostics.Buffering; | ||
internal sealed class PooledLogRecord : BufferedLogRecord, IResettable |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Please add DebuggerDisplayAttribute so that the list of log records in a buffer can be viewed more easily.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Or add the DebuggerDisplayAttribute to SerializedLogRecord, instead.
Remove pooling for now
fa52316
to
fe00658
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=916781&view=codecoverage-tab |
{ | ||
foreach (KeyValuePair<string, object?> ruleAttribute in rule.Attributes) | ||
{ | ||
if (!attributes.Contains(ruleAttribute)) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Can the object?
in the KeyValuePair<string, object?>
be a list; should this have some kind of structural equality comparison then? That seems complex.
Microsoft.Extensions.Logging.LoggerFilterRule has Func<string?, string?, LogLevel, bool>? Filter
, which lets the application developer implement the logic as desired. A similar callback could work here.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Updated with introducing the Filter delegate
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Microsoft.Extensions.Logging.LoggerFilterRule has Func<string?, string?, LogLevel, bool>? Filter, which lets the application developer implement the logic as desired. A similar callback could work here.
Actually, even though the Func<>
delegate is more flexible, we need to stick to IReadOnlyList<KeyValuePair<string, object?>>
because it can be configured and bound from appsettings.json
, while the Func<>
delegate cannot because it is not serializable (at least, not to a human-readable format). The ability to bind from JSON config and refresh the config in runtime is the key feature of this component. Potentially we can add Func<>
later on if users ask for it.
Can the object? in the KeyValuePair<string, object?> be a list; should this have some kind of structural equality comparison then? That seems complex.
Let's stick to the default equality comparer for now and consider accepting custom comparers if users ask for it.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The rules configuration of the standard LoggerFactory does not use the standard configuration binder. Instead, it explicitly reads values from IConfiguration:
I think it would be possible to construct the filter delegate from configuration values in a similar fashion, while allowing the application developer to replace or override this conversion.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Maybe you'll need some custom logic there anyway, if attribute values written to ILogger can be numbers but configuration provides only strings.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Although possibly it can later be extended to:
"Attributes": [
{
"Key": "Duration",
"Type": "System.Double",
"Comparison": ">",
"Value": "2.1"
}
]
where the library would map type names like "System.Double" to objects that know how to parse "2.1" to (double)2.1 and how to implement the ">" comparison. This would use neither Type.GetType(string) nor System.ComponentModel.TypeConverter.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
8319dc8 changed tests:
- AddGlobalBuffer_WithConfiguration_RegistersInDI asserts that
new KeyValuePair<string, object?>("priority", 1)
is included in the attributes of the rule. I expect that this test will fail because values in IConfiguration are always strings and Microsoft.Extensions.Configuration.Binder cannot know that "1" should be converted to Int32. - CanWorkWithValueTypeAttributes asserts that BufferFilterRuleSelector correctly compares the Int32 value of an attribute that is already in a rule.
AFAICT, these tests do not verify that, if ILogger.Log is given a state object that includes an Int32 attribute value, then the value is forwarded to BufferFilterRuleSelector as Int32 rather than first converted to String.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I expect that this test will fail because values in IConfiguration are always strings and Microsoft.Extensions.Configuration.Binder cannot know that "1" should be converted to Int32.
It is not failing. Unless you are talking about some different situation?
Because this PR only supports equality comparisons, rather than < and >, I think floating point is out of scope.
Supporting float numbers and their comparison is not in scope of this feature, at least not in the initial release. For now, for comparison purposes we treat both config and log state as key/value pairs of strings
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I see: GlobalBufferLoggerBuilderExtensionsTests.AddGlobalBuffer_WithConfiguration_RegistersInDI calls Assert.Equivalent(expectedData, options.CurrentValue.Rules)
, which tries to convert the actual value to the type of the expected value or vice versa. So the assertion succeeds and the test passes even though expectedData[0].Attributes[1].Value
is the integer 1 and options.CurrentValue.Rules[0].Attributes[1].Value
is the string "1". But BufferFilterRuleSelector is not so lenient.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Added a custom equality comparer
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=918352&view=codecoverage-tab |
433ede2
to
e5905b1
Compare
e5905b1
to
5fc421c
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=919881&view=codecoverage-tab |
Category = categoryName; | ||
LogLevel = logLevel; | ||
EventId = eventId; | ||
Filter = filter ?? ((_, _, _, _) => true); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
It might be more efficient to leave Filter
as null and not call the filter in that case. I expect that most rules won't have a filter specified and the null check will be well predicted by processors. It would also make rules easier to understand in a debugger as actual filters would stand out better.
src/Libraries/Microsoft.Extensions.Telemetry/LoggerFilterRuleSelector.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/BufferFilterRule.cs
Outdated
Show resolved
Hide resolved
public int? EventId { get; set; } | ||
|
||
/// <inheritdoc/> | ||
public Func<string?, LogLevel?, EventId?, IReadOnlyList<KeyValuePair<string, object?>>, bool> Filter { get; } |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Are there any callsites where Filter is invoked with a null category string, null log level, or null EventId? If yes thats a little surprising but fine as long as we define what that would mean. If no then those parameter types don't need to be nullable.
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/ILoggingBuffer.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBufferManager.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.Extensions.Telemetry/Logging/LoggingEnrichmentExtensions.cs
Outdated
Show resolved
Hide resolved
{ | ||
await context.Request.Body.DrainAsync(default); | ||
|
||
// normally, this would be a Middleware and IHttpRequestBufferManager would be injected via constructor |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
await next(context).ConfigureAwait(false);
}
This is the spot in the middleware where I would expect the majority of logging would occur. Right now it looks like the example code would not buffer that common case logging.
src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBuffer.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferManager.cs
Outdated
Show resolved
Hide resolved
src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/HttpRequestBufferManager.cs
Outdated
Show resolved
Hide resolved
8b8558a
to
e96277f
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=923995&view=codecoverage-tab |
I asked this in one of comments but didn't see answer. Are we going to take these APIs to the design review? |
We are going to take it to API review https://apireview.net. I am not aware of design review, is it different than the API review in .NET? |
No, should be same. You may consult the doc https://github.com/dotnet/runtime/blob/main/docs/project/api-review-process.md for the details. Thanks! |
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=925013&view=codecoverage-tab |
8319dc8
to
8a91c15
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=925328&view=codecoverage-tab |
|
||
public int GetHashCode(KeyValuePair<string, object?> obj) | ||
{ | ||
return HashCode.Combine(obj.Key, obj.Value); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This would have to be obj.Value?.ToString()
, in order to be consistent with Equals.
Alternatively just throw NotImplementedException, if this is designed to be used only with Enumerable.Contains, which doesn't call GetHashCode anyway.
d387358
to
4f524eb
Compare
🎉 Good job! The coverage increased 🎉
Full code coverage report: https://dev.azure.com/dnceng-public/public/_build/results?buildId=925376&view=codecoverage-tab |
namespace Microsoft.Extensions.Diagnostics.Buffering; | ||
|
||
/// <summary> | ||
/// Defines a rule used to filter log messages for purposes of futher buffering. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
"further"
/// <summary> | ||
/// 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 |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This should have docs about what happens if a log entry matches a rule, and what happens if the log entry does not match any rule.
- Is the log entry discarded, buffered, or written directly to underlying loggers?
- Does it cause other log entries to be flushed from the buffer to underlying loggers? If so, does that apply to all log categories or only to the same category?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Alternatively, if this type is used with different semantics in different contexts, then document the behaviour in HttpRequestBufferOptions.Rules and GlobalBufferOptions.Rules, and link to those docs from here.
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