Enables updating the configured min-level overrides at runtime

[bart-vmware]

In response to serilog/serilog-settings-configuration#284 (comment), this PR shows my attempt to add the ability to replace the set of minimum log level overrides at runtime. The goal is to make it possible to refresh when appsettings.json changes on disk.

My approach attempts to avoid compromising performance or multicore contention at:

serilog/src/Serilog/Core/LevelOverrideMap.cs

Lines 35 to 41 in 4d13be5

	// There are two possible strategies to apply:
	// 1. Keep some bookkeeping data to consult when a new context is encountered, and a concurrent dictionary
	// for exact matching ~ O(1), but slow and requires fences/locks; or,
	// 2. O(n) search over the raw configuration data every time (fast for small sets of overrides).
	// This implementation assumes there will only be a few overrides in each application, so chooses (2). This
	// is an assumption that's up for debate.
	readonly LevelOverride[] _overrides;

by atomically updating the LevelOverrideMap reference with a new snapshot, instead of switching to a concurrent collection.

[bart-vmware]

To test this, I changed the sample at https://github.com/serilog/serilog-settings-configuration/blob/dev/sample/Sample/Program.cs in the following way:

Replace:

            var logger = new LoggerConfiguration()
                .ReadFrom.Configuration(configuration)
                .CreateLogger();

with:

            var loggerConfiguration = new LoggerConfiguration()
                .ReadFrom.Configuration(configuration);

            var overridesConfiguration = loggerConfiguration.MinimumLevel.Overrides;

            var logger = loggerConfiguration.CreateLogger();

And replace the logger lines inside the do loop with:

                logger.ForContext(Constants.SourceContextPropertyName, "MyApp.Something.Tricky").Verbose("Hello, world!");
                logger.ForContext(Constants.SourceContextPropertyName, "MyApp.Something.Else").Verbose("Hello, world!");

                Task.Run(() =>
                {
                    var newOverrides = new Dictionary<string, LoggingLevelSwitch>()
                    {
                        ["MyApp.Something.Else"] = new(LogEventLevel.Verbose)
                    };
                    overridesConfiguration.Set(newOverrides);
                }).Wait();

When running, it prints the following output:

[11:01:54  [Information] Args: []
[11:01:54 MyApp.Something.Tricky [Verbose] Hello, world!

Press "q" to quit, or any other key to run again.

[11:01:55 MyApp.Something.Else [Verbose] Hello, world!

Press "q" to quit, or any other key to run again.

[shvez]

commenting to be aware of changes here

[nblumhardt]

Thanks @bart-vmware. If you create all of your loggers outside of the loop (i.e. don't make fresh ForContext() calls after reconfiguring the override map) then I tdon't think the existing loggers will update to reflect the new levels. (This is the kind of predictability issue that might be hard to solve without regressing performance, IIRC.)

[bart-vmware]

Thanks, I see what you mean. I've pushed an additional commit to address that and updated the sample accordingly to make it work:

            var trickyLogger = logger.ForContext(Constants.SourceContextPropertyName, "MyApp.Something.Tricky");
            var elseLogger = logger.ForContext(Constants.SourceContextPropertyName, "MyApp.Something.Else");

            do
            {
                trickyLogger.Verbose("Hello, world!");
                elseLogger.Verbose("Hello, world!");

                // ...

[nblumhardt]

Thanks for taking a look! Unfortunately, the IDisposable implementation on Logger is only exposed on the root logging pipeline; child loggers like those produced by ForContext are exposed only as the non-disposable ILogger, and the API doesn't require or allow disposing these, so the changes would leak all child loggers via their event subscriptions.

The event handling subscribe/unsubscribe/synchronization costs are also a significant factor since in Serilog's design, contextual loggers are cheap/throwaway - it's common to see them created at pretty high frequency.

Digging through this again is reminding me why my conclusions last time were that it's a feature that's somewhat at odds with the way Serilog is designed. Still happy digging in, here, but thinking chances of finding a successful approach might be modest :-)

Just thinking back to your original ticket for a second - have you investigated the reconfigurable "reloadable logger" approach that we currently bundle up with Serilog.Extensions.Hosting?:

https://github.com/serilog/serilog-extensions-hosting/blob/dev/src/Serilog.Extensions.Hosting/Extensions/Hosting/ReloadableLogger.cs

It's fully reconfigurable; it's designed to be eventually "frozen" into a permanent, non-reconfigurable form, but you may have some luck incorporating it/tweaking it to reduce the costs of keeping it in a permanently mutable state 🤔 ... let me know if this might be a lower-effort way to get the behavior you're after.

[bart-vmware]

As far as I'm aware, logger instances are cached and reused when created by LoggerFactory here. As a compromise, we could do the costly event subscription only when the call originates from SerilogLoggerProvider.CreateLogger, but not from child loggers created directly using the public Logger.ForContext. That would enable only long-lived loggers to respond to configuration changes.

ReloadableLogger doesn't fit our use case. It uses extensive locking as-is, but more importantly, our library is not in control of the Serilog initialization. Consuming applications contain the actual Serilog setup code. While it's okay for us to document that consumers need to add something to their configuration or call a built-in Serilog method, we prefer not to interfere much with the Serilog implementation by replacing parts of it, because that's hard to maintain over time when inner workings change.

[nblumhardt]

Thanks for the follow-up. In the typical UseSerilog() configuration, the MEL LoggerFactory isn't invoked - it's replaced by Serilog's. I think your approach might be applicable to how AddSerilog() works, but we generally discourage using it because of other problems around leveling and filtering. HTH!

[sungam3r]

@bart-vmware If you rebase your PR to fresh dev then proposed changes to public API will become observable.

[shvez]

@sungam3r does it mean that we will be able to add new loggers and switch levels on the fly?

[sungam3r]

No. I just said to rebase to incorporate changes from #1783.

[bart-vmware]

@nblumhardt

In the typical UseSerilog() configuration, the MEL LoggerFactory isn't invoked - it's replaced by Serilog's. I think your approach might be applicable to how AddSerilog() works, but we generally discourage using it because of other problems around leveling and filtering.

Yes, I was assuming the use of AddSerilog(). I wasn't aware this is discouraged. Is that documented somewhere?
Either way, if using Serilog through the ASP.NET ILogger abstractions is bad practice, I don't see the point of pursuing this any further.

@sungam3r
Thanks for the heads-up. I'll incorporate your changes at a later time, if at all. Right now, it is more likely that this PR is going to be abandoned unmerged.

[sungam3r]

if using Serilog through the ASP.NET ILogger abstractions is bad practice

I think about that as sync over async or async over sync transitions. If you can use Serilog APIs directly from your code then just use it instead of jumping into MEL layer only to get control back into Serilog some time later.

[bart-vmware]

@sungam3r In an application landscape with various third-party libraries and complex dependencies, having a vendor-neutral logging abstraction in the platform is essential. If every NuGet package that logs took a dependency on Serilog, it would only work if all of them use the exact same Serilog version at any time, worldwide. That's not so practical. That's basically the primary reason why System.Text.Json was created, as well as integrating OpenTelemetry into the platform.

I'm closing this, we no longer have interest in these changes.

[sungam3r]

In an application landscape with various third-party libraries and complex dependencies, having a vendor-neutral logging abstraction in the platform is essential.

I know and because I wrote my own vendor-neutral logging abstraction a long time ago for all projects that I work on 😄. However, it really uses/maps only Serilog. We dropped NLog support a long time ago. Over time, this layer of abstraction is overgrown with its own functionality in addition to the simple adaptation of various logging frmeworks. So we decided to continue using it.

If every NuGet package that logs took a dependency on Serilog, it would only work if all of them use the exact same Serilog version at any time, worldwide.

This can be said for absolutely any package that is very widespread. These are general problems of backward compatibility,

[deathchurch]

Where is it documented that using MSEL combined with Serilog is not best practice? Not sure why you would want to go all in with Serilog when you can use MSEL in code and have Serilog do the heavy lifting in the background.

[sungam3r]

Where is it documented that using MSEL combined with Serilog is not best practice?

I didn't say that. You may combine them, eventually all logging will fall into serilog factory if you use UseSerilog at the app top level. If you can’t do something in your own code via MEL so that it is translated into a Serilog, then just do not do it - use Serilog API directly.

[nblumhardt]

This one's going to be a matter of personal/team tastes. Can't help adding my $0.02 :-)

Reasons I generally use Serilog's APIs directly -

• Static Log class avoids the need to pass loggers around or make everything a container-created component just to consume logging
• LogContext.PushProperty("Name", value) and ILogger.ForContext("Name", value) are marginally more concise than ILogger.BeginScope()
• Fits a wider range of apps/frameworks (doesn't require setting up DI, config, etc.)
• Shorter logging method names :-)

Other than those, I don't think there's much difference at the API level. MEL is a nice enough structured logging abstraction that I can live with either one.

[deathchurch]

Thanks both for the clarification, for a minute I thought I had missed some best practice advice and the MSEL/Serilog combination was not the right thing to be doing.