Commiting batch of log messages conditionally.

[voroninp]

When running in production environment I'd like to have few log messages, if nothing terrible happens.
But in case of failure I need to get all the details and how request was processed.
The problem is that each log entry is independent, and log level is configured on application start.

Describe the solution you'd like

Why not let logger have additional mode of operation?

1. All messages are grouped in a batch (default "size" = all the messages related to processing single request)
2. Sending batchade messages works this way:
   • If there are messages with particular log level, then all messages are sent.
   • Otherwise messeges are filtered according to the configured log level.

For example:
I can have as many LogTrace calls as I want in my code, but these messsages won't appear in log unless I call LogError, which is equivalent to dynamically switching to Trace log level in case of error.

This mode can affect performance however, because all messages should be kepr in memory until batch is completed.

[maryamariyan]

Have you tried using scopes, I feel like that could help group all logs for a certain request into one. And also for filter set configure the log level in appsettings.json

[voroninp]

@maryamariyan But scope does not affect filtering, does it? So if log level is set to Warn all 'Info' will be filtered out in the scope. That's not what I need.

[Bouke]

I was recently thinking of a similar use-case as well. As long as nothing interesting (bad) happens, I don't need to log adjacent messages not meeting the level criterium. However when something interesting happens, I'd like to get all the adjacent messages -- even those below the level criterium.

Take the following pseudo-code:

var provider = new ConsoleLoggerProvider(LogLevel.Warning);
var logger = provider.CreateLogger(...);

using (logger.Scope("Handling request X"))
{
    using (logger.Scope("Performing Authn"))
    {
        logger.LogDebug("Authenticated as Y");
    }
    using (logger.Scope("Performing Authz"))
    {
        logger.LogError("User has no permission!");
    }
}

Currently only the Error message would be logged with its scopes, and the Debug message would be discarded.

What I would like in this contrived example is to record everything that was captured within the outer scope, as there was some message that did meet the level criterium. So even though Debug message doesn't meet the Warning level criterium, it is still recorded as it is in the same (parent) scope as the Error message.

[KalleOlaviNiemitalo]

I have been wondering about whether ILogger.Log<TState> is allowed to save its parameters to a queue, return, and have a different thread examine the TState instance or invoke the formatter delegate later.

• If this is allowed, then my applications cannot safely log TState instances that contain references to mutable (including disposable) or thread-affine objects and lazily read their properties.
• If this is not allowed, then any batching logger has to invoke the formatter delegate or serialize the IReadOnlyList<KeyValuePair<string, object>> before returning. For conditional logging per batch, the logger would have to do this even if no errors have been logged yet.

ConsoleLogger.Log invokes the formatter delegate and then sends the resulting string to the queue. This logging is not conditional per batch though, so it never needs to waste time formatting log entries that would be discarded later. In Microsoft.Extensions.Logging.AzureAppServices, BatchingLogger.Log behaves likewise.

[maryamariyan]

Ah, you're right, scope is not what you need.

The closest thing I can think of that could help with this is to setup filter rules in appsettings.json file and then update it later during the lifetime of the application as needed.

{
  "Logging": {
    "EventSource": { // EventSource provider
      "LogLevel": {
        "Default": "Warning", // All categories of EventSource provider.
        "Microsoft.Hosting": "Trace" // Debug:Microsoft.Hosting category.
      }
    },
    "Console": {
      "LogLevel": {
        "Default": "Debug"
      }
    }
  }
}

[KalleOlaviNiemitalo]

If this is not allowed, then any batching logger has to invoke the formatter delegate or serialize the IReadOnlyList<KeyValuePair<string, object>> before returning.

The Exception exception parameter of ILogger.Log<TState> may also contain references to mutable or thread-affine objects. That makes it difficult to implement batching as an ILoggerFactory that supports providers whose loggers may read properties of exceptions. (Such exceptions would not be fully serializable for remoting either, but binary serialization is being deprecated anyway.)

Another problem is that there is no standard way to report the original time stamp of the log entry to the provider's ILogger when the batch is eventually committed. It seems the best that can be done is to add an {OriginalDateTimeOffset} key to the IReadOnlyList<KeyValuePair<string, object>> and to make the formatter delegate format it as well. Each structured logging provider would have to add support for {OriginalDateTimeOffset}; the batching logger cannot just append {{OriginalDateTimeOffset}} to the value of {OriginalFormat} because the braces would make that ambiguous to parse.

Batching seems much easier to implement as part of a logging provider, where it would know exactly which properties of state and exception need to be preserved.

[KalleOlaviNiemitalo]

whether ILogger.Log<TState> is allowed to save its parameters to a queue

According to #57803 (comment), it is not allowed.

[NightlyRevenger]

That would be useful feature

[KalleOlaviNiemitalo]

IBufferedLogger and BufferedLogRecord were added for this purpose in .NET 9.0. If a logger provider implements IBufferedLogger in the same class as ILogger, then a log buffer can use that to write a series of buffered log records when the buffer is being flushed. Some logger providers support IBufferedLogger already, but not all. This was proposed in #104129 and implemented in #103138.

The missing piece is the log buffer itself and the logic for when to flush the buffer. That API is being proposed in dotnet/extensions#5123 and implemented in dotnet/extensions#5635. Unlike IBufferedLogger, this part looks like it won't be supported on .NET Framework, even though it may be technically compatible.

If the upcoming implementation in dotnet/extensions is not satisfactory, then you can instead implement a custom ILoggerFactory that takes care of the buffering and flushes the buffers to IBufferedLogger when requested. That isn't a trivial job, though. Challenges:

• how to interoperate with Activity like the default LoggerFactory does
• risk of running out of memory if the buffer grows too much
• serialisation of values in structured TState
• serialisation of exceptions