[API Proposal]: Introducing Log buffering abstraction

[tarekgh]

Background and motivation

Currently, apps publish logs to capture telemetry data for monitoring the system's health. Typically, the logged data is sent to a backend for analysis. Often, these logs become useful only when an issue arises, necessitating a review to identify the problem. When the system is functioning normally, the logs are discarded, but the cost of collecting and transmitting them has already been incurred.

Log buffering addresses this by storing logs in memory instead of immediately sending them to the backend. This allows a decision to be made later on whether to send the buffered logs to their destination or discard them, thereby avoiding unnecessary costs.

This log buffering feature will be implemented in the upstream dotnet/extensions library as part of the existing ExtendedLogger design. To enable this feature to work with any logger provider, we need to introduce a buffering abstraction. Logger providers can opt to implement this buffering abstraction interface, which will enable buffering functionality automatically for those providers.

The proposal here focuses on the abstraction types needed in the runtime:

• IBufferedLogger: an interface that logger providers must implement to support buffering.
• BufferedLogRecord: a proposed class used by the infrastructure to hold buffered state in memory. When ready to be flushed out, this object is passed to logging providers without copying.
• BufferedLogRecord is designed to be extendable over time.
• The infrastructure will maintain a pool of BufferedLogRecord objects that are recycled over time. This is an implementation detail for ExtendedLogger.

API Proposal

    namespace Microsoft.Extensions.Logging.Abstractions;
    
    /// <summary> 
    /// Logging providers can implement this interface to indicate they support buffered logging. 
    /// </summary> 
    /// <remarks> 
    /// A logging provider normally exposes an ILogger<T> interface that gets invoked by the 
    /// logging infrastructure whenever it’s time to log a piece of state. 
    /// 
    /// The logging infrastructure will type-test the ILogger<T> object to determine if 
    /// it supports the <c>IBufferedLogger</c> interface also. If it does, that tells the 
    /// logging infrastructure that the logging provider supports buffering. Whenever log 
    /// buffering is enabled, buffered log records will be delivered to the logging provider 
    /// via the <c>IBufferedLogger</c> interface. 
    ///  
    /// If a logging provider does not support log buffering, then it will always be given 
    /// unbuffered log records. In other words, whether or not buffering is requested by 
    /// the user, it will not happen for those log providers. 
    /// </remarks> 
    public interface IBufferedLogger
    {
        /// <remarks> 
        /// Once this function returns, it should no longer access the record objects. 
        /// </remarks> 
        void LogRecords(IReadOnlyList<Microsoft.Extensions.Logging.BufferedLogRecord> records);
    }

    /// <summary> 
    /// State representing a buffered log entry.  
    /// </summary> 
    /// <remarks> 
    /// Objects of this type are reused over time to reduce allocations. 
    /// </remarks> 
    public abstract class BufferedLogRecord
    {
        public abstract DateTimeOffset Timestamp { get; }
        public abstract LogLevel LogLevel { get; }
        public abstract EventId EventId { get; }
        public virtual string? Exception { get => null; }
        public virtual ActivitySpanId? ActivitySpanId { get => null; }
        public virtual ActivityTraceId? ActivityTraceId { get => null; }
        public virtual ActivityTraceFlags? ActivityTraceFlags { get => null; }
        public virtual int? ManagedThreadId { get => null; }
        public virtual string? FormattedMessage { get => null; }
        public virtual string? MessageTemplate { get => null; }
        public virtual IReadOnlyList<KeyValuePair<string, object?>>? Attributes { get => null; }
    }

API Usage

Alternative Designs

No response

Risks

No response

[dotnet-policy-service]

Tagging subscribers to this area: @dotnet/area-extensions-logging
See info in area-owners.md if you want to be subscribed.

[stephentoub]

I'm not following how the system is composed. Where can I see what implementations and consumers of IBufferedLogger look like?

[stephentoub]

For example, I don't understand how the cited pooling of BufferedLogRecord is supposed to work. I implement a logger that implements that interface. Someone hands me a bunch of these record objects transferring ownership to be. How is it that I communicate when I'm done with them?

Or how does this relate to all the existing use of methods like LogInformation?

[tarekgh]

You may look at the PR #103138 showing how the ConsoleLogger is going to implement the interface. The implementation in dotnet/extensions is not done yet but it is in progress for finalizing the design. dotnet/extensions#5123 can give some idea about that.

Cc @noahfalk @geeknoid

[tarekgh]

Someone hands me a bunch of these record objects transferring ownership to be. How is it that I communicate when I'm done with them?

After returning from IBufferedLogger.LogRecords, the ownership goes back to the caller and the records shouldn't be accessed after that by the IBufferedLogger implementer. It is like ILogger.Log, after returning from the method the TState and the exception object shouldn't be accessed by ILogger implementer as the state of these objects can change.

[stephentoub]

After returning from IBufferedLogger.LogRecords, the ownership goes back to the caller

Ok

The implementation in dotnet/extensions is not done yet but it is in progress for finalizing the design. dotnet/extensions#5123 can give some idea about that.

That is a long issue and it's not clear to me what aspects of it address this. This issue needs to be fleshed out with more details, or a link provided to a finalized design, as otherwise we can't really comment on the how appropriate or not the interface is.

If consumption of the interface is being implemented in dotnet/extensions, how does buffering work when someone uses the support in dotnet/runtime? There are lots of very popular extension methods here, and even though we have analyzers that suggest folks use the source generator, the vast majority of code I see that uses ILogger still just uses the extension methods like LogInformation, LogDebug, etc. Those don't light-up with IBufferedLogger?

[stephentoub]

• As I look at the interface more, it seems like the intent is it's at the end of the buffering process, i.e. something is sitting in front of it doing the buffering, and then at some point the buffer is handed off to the logger for everything to be logged immediately? I initially thought the logger itself was responsible for buffering and was signing up for that by implementing this interface.

• Why does LogRecords take an IReadOnlyList? That's an interesting middle ground. If efficiency is desired, I'd have expected the ability to pass in a span. Otherwise, I'd have expected an IEnumerable (and an implementation that wants to index does a type test).

• Why is BufferedLogRecord abstract with all of these abstract / virtual members? e.g. why not have it have a ctor that takes the state for what are currently the abstract members, then have those not be abstract, and have all of the virtual members just be get/set properties?

[tarekgh]

Good questions :-)

The dotnet/extensions library includes ExtendedLogger, an enhanced logger implementation similar to the runtime logger but with additional features. ExtendedLogger maintains a list of all active logger providers registered for logging in LoggerInformation[] Loggers, such as ConsoleLogger. When a log entry is made, ExtendedLogger.Log is invoked, which typically calls the Log method on each logger provider in the loggers list. This process is referred to as "infrastructure" in the issue description.

The proposed enhancement involves adding log buffering functionality. When ExtendedLogger.Log is called and buffering is enabled, the logger will check if each provider in the loggers list implements IBufferedLogger. If a provider does, the log information is extracted into a BufferedLogRecord object, and the actual logging call is deferred. For providers that do not implement IBufferedLogger, the Log method is called as usual.

When it's time to flush the buffered logs, ExtendedLogger iterates through the loggers list again. For each provider implementing IBufferedLogger, it calls LogRecords(IReadOnlyList<Microsoft.Extensions.Logging.BufferedLogRecord> records), passing the list of previously buffered BufferedLogRecord objects.

Extension methods like LogInformation eventually call ILogger.Log, which, in this case, routes to ExtendedLogger.Log. All functionalities, including source generators, are expected to work seamlessly with this setup.

Why does LogRecords take an IReadOnlyList? That's an interesting middle ground. If efficiency is desired, I'd have expected the ability to pass in a span. Otherwise, I'd have expected an IEnumerable (and an implementation that wants to index does a type test).

I assume you meant Span<BufferedLogRecord>. Would it need to be backed by an array? This would mean ensuring the array grows as needed and possibly shrinks when the load is low. Using a collection like List might be simpler than using Span. Perhaps you have a better idea 😄. Using IEnumerable in the method interface could also be a good option, I guess.

Why is BufferedLogRecord abstract with all of these abstract / virtual members? e.g. why not have it have a ctor that takes the state for what are currently the abstract members, then have those not be abstract, and have all of the virtual members just be get/set properties?

We anticipate that buffering will generate many BufferedLogRecord objects, and not all properties within these objects will always be needed. For instance, if the configuration doesn't require logging activity data, the BufferedLogRecord implementation can omit the backing store for the activity properties. This will make the object smaller and reduce overall memory consumption for buffering. Therefore, most properties are virtual and optional to override, returning null by default to avoid unnecessary backing storage.

[KalleOlaviNiemitalo]

Would these types be shipped in the Microsoft.Extensions.Logging.Abstractions package? If so, it would then have to depend on the System.Diagnostics.DiagnosticSource package on .NET Framework and .NET Standard, in order to get the definitions of ActivitySpanId, ActivityTraceId, and ActivityTraceFlags. Not an objection; I'd just like to understand the plan.

Does BufferedLogRecord.FormattedMessage include BufferedLogRecord.Exception, or is it separate?

[tarekgh]

Would these types be shipped in the Microsoft.Extensions.Logging.Abstractions package?

Yes. The dependency on System.Diagnostics.DiagnosticSource will not be different than any other Microsoft.Extensions.* libraries that currently depend on System.Diagnostics.DiagnosticSource.

Does BufferedLogRecord.FormattedMessage include BufferedLogRecord.Exception, or is it separate?

It makes sense to be separate and let the logger provider decide how to log the exception.

[skyoxZ]

How does BufferedLogRecord.FormattedMessage be set?

How does it support structured logging?

[KalleOlaviNiemitalo]

Structured logging seems to be supported via BufferedLogRecord.Attributes. I presume the object in KeyValuePair<string, object?> would be a deep copy if the original is mutable.

I'd expect ILogger.Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState,Exception?,string> formatter) to call formatter.Invoke(state, exception) right away and store the result as BufferedLogRecord.FormattedMessage, unless message formatting is disabled in the logger factory.

[KalleOlaviNiemitalo]

These types might be better placed in the Microsoft.Extensions.Logging.Abstractions namespace) than in Microsoft.Extensions.Logging because, like NullLogger and LogEntry<TState>, they are more relevant to authors of logger providers and logging infrastructure than to applications that configure logging and write log entries.

[KalleOlaviNiemitalo]

    /// A logging provider normally exposes an ILogger<T> interface that gets invoked by the 
    /// logging infrastructure whenever it’s time to log a piece of state. 

No, the logging provider exposes the non-generic ILogger interface, and the infrastructure provides an ILogger<TCategoryName> wrapper.
(Noticed this while trying to implement the buffered logging API in a provider.)

[KalleOlaviNiemitalo]

How does buffering work with ILogger.BeginScope<TState>(TState state)? I don't see a scope-list property in BufferedLogRecord.

Does the logging infrastructure have to embed the scope information into BufferedLogRecord.FormattedMessage and BufferedLogRecord.Attributes? (That would not work with logger providers such as TraceSourceLoggerProvider that have to forward the BeginScope calls to some other API, but I guess those would just not implement IBufferedLogger, like they already don't implement ISupportExternalScope.)

Or, do all BufferedLogRecord instances in the same IBufferedLogger.LogRecords call belong to the same logger scope? In which case, the logging infrastructure would have to either flush the buffer whenever a scope ends, or copy the logger scope TState objects so that it can safely buffer the scope changes too.

[tarekgh]

These types might be better placed in the Microsoft.Extensions.Logging.Abstractions namespace) than in Microsoft.Extensions.Logging

Right. This was just a typo. It makes sense the new types be next to LogEntry<TState>. I fixed that in the proposal.

[Ilchert]

When it's time to flush the buffered logs, ExtendedLogger iterates through the loggers list again.

@tarekgh It is not clear for me, how to control this time to flash? Are you going to add more api to control when it should be flushed, and should it be flushed at all?

[tarekgh]

@Ilchert there will be a whole feature implemented in the extension's library next to extended logger there. This will include APIs and configurations support for buffering. The proposal here is only scoped to the abstraction needed in the runtime to support implemented the feature.

CC @evgenyfedorov2 @geeknoid

[terrajobst]

Video

• LogRecords should take an IEnumerable<T>

namespace Microsoft.Extensions.Logging.Abstractions;

public interface IBufferedLogger
{
    void LogRecords(IEnumerable<BufferedLogRecord> records);
}

public abstract class BufferedLogRecord
{
    public abstract DateTimeOffset Timestamp { get; }
    public abstract LogLevel LogLevel { get; }
    public abstract EventId EventId { get; }
    public virtual string? Exception { get; }
    public virtual ActivitySpanId? ActivitySpanId { get; }
    public virtual ActivityTraceId? ActivityTraceId { get; }
    public virtual ActivityTraceFlags? ActivityTraceFlags { get; }
    public virtual int? ManagedThreadId { get; }
    public virtual string? FormattedMessage { get; }
    public virtual string? MessageTemplate { get; }
    public virtual IReadOnlyList<KeyValuePair<string, object?>>? Attributes { get; }
}