dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
15.18k stars 4.72k forks source link

[API Proposal]: Support fingers-crossed mode for logging. #101054

Closed voroninp closed 4 months ago

voroninp commented 6 months ago

Background and motivation

When things go wrong, it's better to know as much as possible, when everything works fine, silence is rewarding. Logging should support this behavior.

The main idea is to introduce a section within which all log messages are cached until a message with certain level ( + category?) is logged. If this does not happen, all messages are discarded.

PHP Symfony's Monolog has this mode

API Proposal

Add method to ILoggerFactory (breaking change unless default implementation is provided):

public interface ILoggerFactory
{
    public IDisposable StartGrouping(LogLevel logAtLevel)
    {
        throw new NotSupportedException();
    }
}

API Usage

using var loggingGroup = _loggerFactory.StartGrouping(logAtLevel: LogLevel.Error);
_logger.LogInformation("Hello world!");
_logger.LogCritical("Apocalypse now!");

Both messages are logged.

using var loggingGroup = _loggerFactory.StartGrouping(logAtLevel: LogLevel.Error);
_logger.LogInformation("Hello world!");
_logger.LogWarning("Boeing opened another door!");

Neither of the messages get logged, because section did not contain logging with Error level.

Alternative Designs

No response

Risks

Keeping all log messages for the group, especially if it spans the entire request, negatively affects the performance. On the other hand, Activity api already has similar behavior.

Another config section is required for letting or prohibiting loggers of certain categories to join the group. For example, I may be interested only in grouping log messages coming from my code.

If logging occurs inside grouping section and logger is allowed to join the group, ILogger.IsEnabled(...) should return true for the checks (especially relevant for source generated code):

if (_logger.IsEnabled(level))
{
    _logger.Log(...);
}
dotnet-policy-service[bot] commented 6 months ago

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

KalleOlaviNiemitalo commented 6 months ago

Buffering the log entries in LoggerFactory is difficult because, after ILogger.Log returns, the caller may recycle or otherwise invalidate the state object that it passed there. So the LoggerFactory would have to synchronously convert all data to strings or other safe types and store those results in the buffer. This conversion could then interfere with logger-provider features that recognize other types.

If LoggerFactory instead passed the buffering request to each logger provider, that problem would not exist. But then you'd have a separate buffer in each logger provider, increasing the amount of memory needed.

voroninp commented 6 months ago

Log returns, the caller may recycle or otherwise invalidate the state object that it passed there.

Yes, you are right. This is indeed a predicament ='(. I'd prefer analyzer to emit a warning, if I pass complex objects as arguments to Log method. In most cases values are primitive types: ints, strings, dates.

ChrML commented 6 months ago

We did-ish something like this with a custom provider. But we only keep a ring-buffer of readily formatted messages. That are conditionally logged if more important things happen later.

voroninp commented 6 months ago

@ChrML , there's a Seq sink https://github.com/alexeyshockov/Serilog.Sinks.FingersCrossed for this, but it won't work for logging with source generator, because the generated code explicitly checks log level.

tarekgh commented 4 months ago

Looks this can be addressed by https://github.com/dotnet/extensions/issues/5123.

CC @evgenyfedorov2 @geeknoid @noahfalk

geeknoid commented 4 months ago

Yes, we're aiming to add support for both sampling and buffering. Buffering keeps data in memory until/if a trigger happens, at which point the data is sent down the wire.

Large active services can log a lot of state, and most of it is for naught. Yet, even though nobody looks at the data 99% of the time, generating, processing, and storing all this data costs a pretty penny. If we can avoid generating logs when everything is good, we think this can lead to quite substantial COGs improvements for the service.

tarekgh commented 4 months ago

I am closing this issue here. @voroninp feel free to respond on https://github.com/dotnet/extensions/issues/5123 if your scenario still missing features there. Thanks for your report.