.NET Core 2.0 minimum level handling/roadmap

[nblumhardt]

The current provider works with .NET Core 2.0, but the APIs have shifted since the 1.x version and I'm not confident we've got a decent story here now.

.NET Core 2.0 has its own internal "minimum level" that will be set to Information regardless of what we do in Serilog, unless we play in the JSON configuration system introduced with that version:

datalust/seq-extensions-logging#22

The net effect will be that apps using Serilog today will have to either separately specify ILoggingBuilder.SetMinimumLevel() in addition to the Serilog minimum level, or add a "Serilog.Extensions.Logging.SerilogLoggerProvider" element to the "Logging" configuration section in appsettings.json with level configuration specific to Serilog, even if this duplicates what's already been set through LoggerConfiguration.

(We can improve this experience by adding [ProviderAlias("Serilog")] to SerilogLoggerProvider, but, it just wins us a shorter key under "Logging", no other improvement in level handling.)

The conundrum we're facing is: the Serilog level and level overrides are set via LoggerConfiguration. When we call loggingBuilder.AddSerilog(), we don't communicate to .NET Core that we're handling our own levels. So, the framework will apply an Information filter, regardless.

I'm not sure what ways forward are open to us; it doesn't look like .NET Core 2.0 allows any level configuration to take place via Serilog (MinimumLevel, MinimumLevel.Override()) without the user duplicating all of that configuration now through Microsoft.Extensions.Logging's APIs.

(About all I can come up with is taking the nuclear option and completely replacing the whole logging subsystem with a Serilog one, but that will paint us into a corner of another kind.)

Needing some guidance here - any help appreciated @pakrym @davidfowl & co.

[pakrym]

Couple notes:

1. Logging filter configuration comes from LoggerFilterOptions object in DI it is bound to JSON configuration by default but can be changed by usual means of services.Configure<LoggerFilterOptions>()

2. You can always call loggingBuilder.AddFilter<SerilogProvider>(null, LogLevel.Trace) in AddSerilog and we will forward all messages to Serilog if not specifically overridden by user.

[skomis-mm]

loggingBuilder.AddFilter< SerilogLoggerProvider >(null, LogLevel.Trace)

👍
Seems like this is what we are missing in Serilog.Extensions.Logging

Btw, plain upgrade to .net core 2.0 preserving ILoggingFactory.AddSerilog in the code doesn't introduce this kind of behavior change.

[kdaveid]

@skomis-mm: But on WebHostBuilder().ConfigureLogging(...) with asp.net core 2.0 you don't have direct access to ILoggerFactory anymore. This is the recommended way of adding services. You would have to build a Service Provider first and get the ILoggerFactory first out.

[nblumhardt]

Thanks for all the weigh-in, folks! I think the extra AddFilter call is a good workaround to get us out of the current hole 👍.

I've done some more digging, and have had good results with:

public static void Main(string[] args)
{
    Log.Logger = new LoggerConfiguration()
        .MinimumLevel.Debug()
        .WriteTo.Console(theme: AnsiConsoleTheme.Code)
        .CreateLogger();

    var host = new WebHostBuilder()
        .UseKestrel()
        .UseContentRoot(Directory.GetCurrentDirectory())
        .UseIISIntegration()
        .UseStartup<Startup>()
        .ConfigureServices(collection => collection.AddSingleton<ILoggerFactory>(new SerilogLoggerFactory()))
        .Build();

    host.Run();
}

SerilogLoggerFactory is really simple, I'll paste it in below. With this in place, "Logging" can be completely removed from appsettings.json (replaced with "Serilog" if you want to do JSON config there).

Why I like this:

• There's only one set of level controls/filters - everything just works, efficiently, via the one Serilog configuration
• There's no crazy console-via-MEL-but-other-things-via-Serilog confusion
• You only get the loggers you actually ask for, no defaults to remove etc.
• It's back to using MEL purely as a facade, as it was originally intended (no extra layers of filtering &c.)
• You actually get logging configured before hitting any other components that may fail, so just adding try/catch around the web host builder enables full exception handling

Factory:

public class SerilogLoggerFactory : ILoggerFactory
{
    readonly SerilogLoggerProvider _provider;

    public SerilogLoggerFactory(Serilog.ILogger logger = null, bool dispose = false)
    {
        _provider = new SerilogLoggerProvider(logger, dispose);
    }

    public void Dispose()
    {
        _provider.Dispose();
    }

    public ILogger CreateLogger(string categoryName)
    {
        return _provider.CreateLogger(categoryName);
    }

    public void AddProvider(ILoggerProvider provider)
    {
        SelfLog.WriteLine("Ignoring added logger provider {0}", provider);
    }
}

I'm going to PR the quick-fix into 2.0, and create another PR with the factory and updated docs for a 3.0.

Thoughts/feedback welcome 👍

[nblumhardt]

Updated Program.cs, with some extension method goodness and full EH:

public static int Main(string[] args)
{
    Log.Logger = new LoggerConfiguration()
        .MinimumLevel.Debug()
        .WriteTo.Console(theme: AnsiConsoleTheme.Code)
        .CreateLogger();

    try
    {
        var host = new WebHostBuilder()
            .UseKestrel()
            .UseContentRoot(Directory.GetCurrentDirectory())
            .UseIISIntegration()
            .UseStartup<Startup>()
            .UseSerilog()
            .Build();

        host.Run();
        return 0;
    }
    catch (Exception ex)
    {
        Log.Fatal(ex, "Unhandled exception");
        return 1;
    }
    finally
    {
        Log.CloseAndFlush();
    }
}

[analogrelay]

I think you'd want .MinimumLevel.Verbose() no? Trace (which maps to Verbose, I believe) is lower than Debug.

[analogrelay]

Would it be a terrible idea to have an overload .UseSerilog(this IWebHostBuilder builder, Action<LoggerConfiguration> configuration, bool dispose = false)? (and maybe even making that the only one? If you want to build the logger yourself there's always .AddSerilog ...). I ask that way because I'm not sure how I feel about it myself 😝.

That way, the configuration we give you in the lambda can be preconfigured with some sensible M.E.L defaults. It feels like a way to encourage people into the happy path of making sure the basic settings aren't going to get in their way, but still gives them all the necessary opt-outs.

[davidfowl]

Yes, coupling serolig to our host would be terrible.

[nblumhardt]

@anurse thanks for the ideas!

The minimum level is just an example - could use anything in there 👍 - I've just PR'd an updated sample showing how this can work with JSON config as well: https://github.com/nblumhardt/serilog-extensions-logging/blob/a95aed3de69f18e3e36019afb53b26dab84a2282/samples/SimpleWebSample/Program.cs

The advantage of creating the Serilog logger outside of all the web hosting/DI stuff is that a lot of failures really do happen early in start-up, and this way we can log them. (Throwing constructors, DI registration problems, type loading problems...).

the configuration we give you in the lambda can be preconfigured with some sensible M.E.L defaults.

What kinds of defaults do you mean? Serilog already has its own sensible defaults, which would apply here :-)

@davidfowl thanks for taking a look. I think the UX is the right one; we might want to ship it in a separate package, but, there's no reason for Serilog to have a clunkier experience than AI (with its UseApplicationInsights()), for example. As soon as we require touching ServiceCollection or ILoggingBuilder, there will be the opportunity to call methods that would no longer be supported, like AddLogging() or AddConsole(). Is this what you meant?

[pakrym]

@nblumhardt I would vote against replacing ILoggerFactory completely, this would cause user to lose couple useful integrations we provide (AI logging support, AppServices diagnostics log support)

These integrations are combination of hosting startup and logger providers being resolved from DI by LoggerFactory implementation.

[nblumhardt]

Hey @pakrym - thanks for the feedback.

this would cause user to lose couple useful integrations we provide (AI logging support, AppServices diagnostics log support)

The user can opt into these through Serilog, e.g. https://github.com/serilog/serilog-sinks-applicationinsights, and via the file logger for Azure App Services. It's cool to have it all set up out of the box, but in the balance vs. a better Serilog experience for all sinks, it seems like requiring an extra LOC for AI integration is pretty reasonable.

We've so far done everything we can to make the MEL/Serilog experience great for everyone regardless of sinks, preferred APIs, etc., and if there's a better way we can give this experience I'm all-in to support it.

MEL v2 seems to be a step back for user experience with Serilog, though, so I really want to fix that ahead of all other considerations. Right now replacing the ILoggerFactory does seem to be the only way to get to a configuration story that's not going to be penalized by double-handling.

Although MEL's heading much more towards being an implementation, rather than a facade, in v2, can we reverse that trend? What would it take to offer Serilog as an option for the core log routing/handling out of the box? Could we still enable things like AI integration by default? Definitely open to ideas.

[nblumhardt]

(Footnote: exploring the case for enabling Serilog as a first-class option out-of-the-box: https://www.nuget.org/packages?q=Tags%3A%22serilog%22 - there's a tonne of functionality out there we could help people connect with, instead of reinventing all of this all over again for MEL.)

[davidfowl]

MEL v2 seems to be a step back for user experience with Serilog, though, so I really want to fix that ahead of all other considerations. Right now replacing the ILoggerFactory does seem to be the only way to get to a configuration story that's not going to be penalized by double-handling.

Thats a big hammer. I'd rather work on fixing anything we can tactically and telling people to use the existing ILoggerFactory extension method rather than doing this.

Although MEL's heading much more towards being an implementation, rather than a facade, in v2, can we reverse that trend? What would it take to offer Serilog as an option for the core log routing/handling out of the box?

A few things come to mind:

• Have alternative sinks for whatever we ship OOTB
• Making the dependencies minimal for each of the serliog sinks
• First class configuration experience using IConfiguration

Could we still enable things like AI integration by default? Definitely open to ideas.

What's the benefit here? I'm not sure this saves anything.

[davidfowl]

Another thing that is worrying about relying too much on a single implementation is that the abstraction needs to be flexible enough to work for multiple logger provider implementations (like DI). That obviously can be solved even if serilog is the "default" choice.

[analogrelay]

What kinds of defaults do you mean? Serilog already has its own sensible defaults, which would apply here :-)

In my mind, when using Serilog purely as a sink for M.E.L, you'd want the Minimum Level filter "removed" (or set to the broadest form) from Serilog, because it's really confusing to have to deal with both versions. That's what I'm referring to with sensible M.E.L defaults.

Yes, coupling serolig to our host would be terrible.

How is a .UseSerilog extension off WebHostBuilder any more coupled than AppInsights, which does exactly this?

[nblumhardt]

Thanks for all the replies, appreciate you taking the time. Here are my thoughts:

How is a .UseSerilog extension off WebHostBuilder any more coupled than AppInsights, which does exactly this?

👍

Another thing that is worrying about relying too much on a single implementation

That's the problem here, though - once MEL implements its own levels, filters and so-on, it's another implementation, not an abstraction. Being able to swap in Serilog completely (even as an option, not necessarily a default), would help keep assumptions about the logging implementation explicit.

Could we still enable things like AI integration by default? Definitely open to ideas.

What's the benefit here? I'm not sure this saves anything.

I'm assuming that having AI out of the box is one of the goals of the experience, or at least the template. Being able to meet those goals (or whatever other aims there are for the default experience) while relying on another logging implementation seems like it will be important.

Thats a big hammer. I'd rather work on fixing anything we can tactically and telling people to use the existing ILoggerFactory extension method rather than doing this.

As a framework user, here's what I want, personally, out of logging and the framework in general:

• One place to set up logging; I don't want to double-handle things - if I'm using Serilog, I just want to set up Serilog, tell the framework about it, and go on my merry way
• Consistent experience; if I am using Serilog, I don't want MEL's ILoggers to behave any differently from the Serilog ones - levels should be the same, log destinations should be the same (this is a problem for AI in the default setup - if I use Serilog.Log.Information() it won't go to AI, though ILogger<T>.LogInformation() will)
• No tangle between logging and DI; I've done enough work with both to know that large apps have complex DI setups, and I'd prefer to have logging report on errors in DI configuration rather than have to go to some secondary source the framework chooses for me
• No bloat; when I first started debugging this, I used ILoggingBuilder.AddSerilog() and then checked out the configured providers: I've just set up a complete logging framework - why are there 7 logging providers configured?

If using Serilog means effectively running two logging frameworks in process, it's going to be a hard sell. People are already very sensitive about complexity and perf in the logging pipeline. Ditto for correctness - if my logging works one way through MEL's interfaces, and another way through Serilog's, how am I going to be sure my logging is actually working correctly? Removing Serilog from the equation here would be the only way to ensure all logging ends up at the intended targets.

You can see what I'm getting at here - any intrinsic penalty for using Serilog will seriously hurt this project in the long run. Even this would be defensible if the alternative was equally functional - but in reality, users will end up making do with a currently much less capable logging solution just to remove the friction and complexity that the APIs would force upon us.

Where things stand right now, it seems like the only solution likely to work is to support a world where users can choose MEL, Serilog, or NLog on equal terms. Replacing ILoggerFactory completely demonstrates that, as things stand with 2.0, we've got the APIs necessary to do this (yay! And +1 for providing it.)

Hence it'd be great to turn the discussion towards: if we're going to have Serilog, MEL and NLog on an equal footing, what problems does that create for anyone else, and how can we (Serilog, NLog, others) help to solve them?

[nblumhardt]

Just re-reading:

Hence it'd be great to turn the discussion towards: if

In case that is easy to read the wrong way :-) I don't mean to shut down the discussion, only that there's another way to look at this that could be more fruitful.

[davidfowl]

Where things stand right now, it seems like the only solution likely to work is to support a world where users can choose MEL, Serilog, or NLog on equal terms. Replacing ILoggerFactory completely demonstrates that, as things stand with 2.0, we've got the APIs necessary to do this (yay! And +1 for providing it.)

I don't buy that conclusion. We went down this path in the beginning of 2.0 and it broke scenarios where existing providers (like app insights and EF) had to know what logger factory was registered so that they could add the right provider. It's very similar to DI in that, if a library needs add registrations to the container, they don't want to write bindings for each DI container. What you're suggesting takes us down that path and I don't think it's a very successful one.

[nblumhardt]

Thanks for the follow-up. Just so I can understand your point better - I know about the AI provider but haven't looked at any for EF. Where does EF integrate into the logging pipeline currently?

[merbla]

A few thoughts.

In the Serilog ecosystem, we often see users choose to use Serilog and go all in. Previously I have viewed a log provider analogous to a Serilog Sink (please correct my understanding), and as such it is a similar construct.

I have not seen many instances that attempted to use MEL, with multiple providers and Serilog with multiple sinks.

e.g.

MEL
-> AI Provider 
-> Console Provider
-> Serilog Provider
	-> Sinks (SQL Server, Elastic)

Rather, they opt to setup Serilog and extend from there.

e.g.

MEL 
-> Serilog 
	-> Sinks (Console, AI, SQL Server, Elastic)

As such, I think we should have hooks/sytantic sugar to get a developer up and running in this way. In this case UseSerilog as seen here #101.

Secondly, I am trying to understand how this discussion relates/impacts the alternative setup mentioned here

Most of this discussion has focused around the use of the following:

var host = new WebHostBuilder()
	.UseStartup<Startup>()
 	.Build();

Are there any considerations required for the CreateDefaultBuilder shortcut setup?

e.g.

var host = WebHost.CreateDefaultBuilder(args)
        .UseStartup<Startup>()
        .Build();

Finally, there seems to be an undertone/push to preserve previous AI integration work that occurred in 1.x. It has been mentioned a few times in the comments above. Is there any reason for this?

[davidfowl]

I have not seen many instances that attempted to use MEL, with multiple providers and Serilog with multiple sinks.

You may not have seen it but it happens all of the time. The moment a library needs to consume logs you're in a bind. That library now needs to know what logger factory was configured by the application in order to work.

Finally, there seems to be an undertone/push to preserve previous AI integration work that occurred in 1.x. It has been mentioned a few times in the comments above. Is there any reason for this?

The undertone is about libraries that want to consume logs without knowing about a specific logger implementation. Right now you can produce logs by using ILogger and you can consume logs by writing an ILoggerProvider. If we're telling everyone to use serilog as the abstraction itself, then we may as well delete MEL and tell the other logger providers to write sinks for serilog as well (serilog -> nlog).

Now, if there was no provider abstraction for MEL at all the you would always need another library (like serilog) to consume.

FWIW we went deep down this rabbit hole early in 2.0 aspnet/Logging#420 (comment). We came to the conclusion that it was too breaking with low ROI.

Finally see aspnet/Hosting#1071 for the issue I described above.

[merbla]

Thanks @davidfowl for the concrete example.

[nblumhardt]

Thanks guys. There's a lot of history, and many rabbit-holes already explored, but we still need to course-correct:

1. MEL v1 was a fairly thick abstraction, but v2 is an implementation by any practical measure
2. Users don't want to deal with two logging frameworks in one app (me included :-)), with obvious consequences for Serilog
3. We can avoid this, and create a first-class experience from the Serilog side, by providing UseSerilog()
4. Doing so doesn't accommodate everything that MEL enables out-of-the-box, like pluggable listeners or unified configuration
5. ?

Problem (4.) isn't enough to discount (3.) as a way forward. .NET Core is all about being lean-and-mean. A healthy ecosystem requires that Serilog, NLog and others can provide a completely first-class developer experience without friction or bloat. It's (5.) we have to fill in.

As at v2, we're all okay: we can merge #101 and provide UseSerilog() with some caveats, and on the MEL side, the scenarios that are needed out of the box are there for anyone who wants them. Neither is without trade-offs, but we'll be fine until a 2.1 or 3.0 ships, and no one will miss the boat.

It's not clear if there will be any high-level scenarios we miss: Serilog's had AI integration for ages, for example, and we can look at PRs to close any gaps. Right now, Serilog supports many, many providers, including AI, the console (with JSON highlighting and themes!), event log, etc. On the configuration side, we support not just IConfiguration, but <appSettings> and key-value-pairs in memory, too.

As a fallback, we also provide integration with ILoggingBuilder already, so anyone who wishes to use only MEL but needs to plug in Serilog for some missing sink can do that without being forced by us to jump through any hoops.

So... I think we should review and merge #101 ASAP. Following on close behind, though, we should:

1. Gather the list of gaps this will leave, including the future aims the .NET team is working towards; I can start a new thread for this
2. Propose some solutions and get them implemented - improvements or extensions to the Serilog provider, new APIs, routing events through trace listeners, alternative providers supported out-of-the-box, etc., etc. - whatever it takes to meet everyone's needs
3. Forget about all of this plumbing and get on with building more awesome things

Sounds like a plan?

[davidfowl]

As a fallback, we also provide integration with ILoggingBuilder already, so anyone who wishes to use only MEL but needs to plug in Serilog for some missing sink can do that without being forced by us to jump through any hoops.

That sounds good! We'll be able to keep parity with what 1.0 has today.

So... I think we should review and merge #101 ASAP. Following on close behind, though, we

This line of code is the problem https://github.com/serilog/serilog-extensions-logging/pull/101/files#diff-76102dabbdfef9091d353926bc8bdfb8R42.

People that call UseSerilog will all of a sudden break the end to end AI integration experience we expose, but maybe that's fine as it isn't the default OOTB story. You'll also break EF's internal logging infrastructure https://github.com/aspnet/EntityFrameworkCore/blob/f4c9f4c4be0e6f159506e583eda0ba68536356b2/src/EFCore.Design/Design/Internal/DbContextOperations.cs#L101. It'll also break anybody else calling AddProvider in their Startup class.

As part of this change you should decide if this should throw rather than no-op. I don't know what's better, I can only tell you we've been down this road and it wasn't worth the effort.

[nblumhardt]

@davidfowl 👍

decide if this should throw rather than no-op

In the EF case, it seems like they'd continue to work if we just forwarded everything straight through to them.... I wonder if that's option 3?

(EF subscribing to logs itself is a really weird integration, BTW - are they trying to do correlation on behalf of the log collector? I need to learn more about what's going on in there..)

[nblumhardt]

(Just waking up the tree, it looks like the EF stuff is design-time , so may not turn out to be too much worry. I'll flick them a note/link to this discussion anyway. Thanks!)

[AceHack]

I just want to say UseSerilog is not useful to me as someone who wants to use MEL, I just needed a sync from Serilog. I have other syncs like Console and AI that I want to use MEL, only for special elastic search do I need serilog.