Logging in DI #626

pakrym · 2017-05-24T16:00:15Z

pakrym · 2017-05-24T16:04:12Z

Idea is to move ILoggerProviders to DI and use existing options infrastructure to manage logger configuration/filtering.

/cc @cwe1ss @nblumhardt @khellang

davidfowl · 2017-05-24T16:45:51Z

We should add an AddProvider extension method off ILoggerbuilder

pakrym · 2017-05-24T16:55:45Z

@davidfowl done

khellang · 2017-05-24T18:46:27Z

I've mentioned it before, but I'll say it again; I'm really not a fan of changing the return type (to ILoggerBuilder). It breaks chainability and forces me away from using expressions.

IMO, It's a much better alternative to use Action<ILoggerBuilder>. The pattern is already scattered around the different repos, but it's not really consistent, and I seem to remember some pushback on the pattern way back. What are the guidelines on this now?

Other than that, I think this looks pretty awesome!

pakrym · 2017-05-24T20:07:49Z

@khellang I think it makes sense to take delegate if it's execution is deferred. In case of logging we would have to immediately execute it because the only thing it does is mutating service collection. So in case of logging we decided to go the same way MVC did (IMvcBuilder) and return a builder.

khellang · 2017-05-24T20:46:39Z

I think it makes sense to take delegate if it's execution is deferred.

It also makes sense for scoping, i.e.

var provider = new ServiceCollection()
    .AddLogging(logging => { /* providers can only be added in here */ })
    .BuildServiceProvider();

as opposed to

var services = new ServiceCollection();
var loggingBuilder = services.AddLogging();
// providers can be added here...
var provider = services.BuildServiceProvider();
// what happens if you try to add a provider here?

So in case of logging we decided to go the same way MVC did (IMvcBuilder) and return a builder.

Yeah, I realize there's a mixture of I*Something*Builder and the Action<I*Something*Builder> throughout the APIs. AFAIK, Entity Framework does something similar. That's why I asked

What are the guidelines on this now?

There's even new APIs in this PR, like Action<ConsoleLoggerOptions>. That's not deferred, is it?

Anyway, it's pretty easy to wrap these kinds of APIs in extension methods to achieve what I want, like

public static class ServiceCollectionExtensions
{
    public static IServiceCollection AddLogging(this IServiceCollection services, Action<ILoggingBuilder> configure)
    {
        configure(services.AddLogging());
        return services;
    }
}

So it's not really a big deal 😄

nblumhardt

I added a few notes as I read through the changeset; guessing most of these are due to WIP, but recorded them in case anything is useful :-)

nblumhardt · 2017-05-24T21:19:06Z

src/Microsoft.Extensions.Logging.TraceSource/TraceSourceFactoryExtensions.cs

-        public static LoggerFactory AddTraceSource(
-            this LoggerFactory factory,
+        public static ILoggerBuilder AddTraceSource(
+            this ILoggerBuilder collection,


This argument is called collection in some, and builder in other similar methods.

nblumhardt · 2017-05-24T21:25:16Z

src/Microsoft.Extensions.Logging/ConfigurationLoggerFilterConfigureOptions.cs

+            }
+        }
+
+        public string ExpandLoggerAlias(string name)


This doesn't seem like a scalable API; it'll also deter users from stepping beyond these basic providers because the natural guess will be wrong. I.e., if I'm a user looking at an existing configuration, and want to add a new one for, say, a file, I'll try "File" and nothing will happen... It also seems a bit questionable to favor, say, Azure App Services, but not Seq, Splunk, Elasticsearch, CloudWatch....

Yep, it's temporary, we would way to extend the list.

nblumhardt · 2017-05-24T21:28:06Z

src/Microsoft.Extensions.Logging/ILoggerBuilder.cs

+
+namespace Microsoft.Extensions.Logging
+{
+    public interface ILoggerBuilder


Why introduce ILoggerBuilder at all, here? If it's just a wrapper for IServiceCollection, and all the provider extension methods do is dot through to Services, isn't this unnecessary ceremony?

We want to prevent all logging related methods appearing on IServiceCollection. If we keep them on IServiceCollection they would also need to be named in more verbose way (AddConsoleLogger, AddLoggingFilter, etc. )

nblumhardt · 2017-05-24T21:28:58Z

src/Microsoft.Extensions.Logging/LogMessageFilter.cs

@@ -0,0 +1,4 @@
+namespace Microsoft.Extensions.Logging
+{
+    public delegate bool LogMessageFilter(string loggerType, string categoryName, LogLevel level);


This seems more like a LogCategoryFilter or something like that - it doesn't touch the log message itself.

I'm thinking about removing it all together because most AddFilter overloads are forced to use Action<*> as filter delegates.

nblumhardt · 2017-05-24T21:29:53Z

src/Microsoft.Extensions.Logging/Logger.cs

            {
                return;
            }

            List<Exception> exceptions = null;
-            foreach (var loggerInfo in _loggers)
+            foreach (var loggerInfo in Loggers)


Race condition; Loggers is public and might have been set to null between this and the check above.

nblumhardt · 2017-05-24T21:42:44Z

I think it'd be good to state the goals of this PR a bit more clearly. Is there really much benefit building logging atop DI? (Apologies if I've overlooked an earlier discussion around this.)

In most apps I've worked on, we've gone to great pains to configure logging at start-up and stand it up independently of anything as complex as DI. Configuration errors in happen all the time, and often they're environment specific, so getting log events out even if DI configuration crashes is pretty useful.

epignosisx · 2017-05-25T01:57:29Z

@nblumhardt I agree with you about

In most apps I've worked on, we've gone to great pains to configure logging at start-up and stand it up independently of anything as complex as DI. Configuration errors in happen all the time, and often they're environment specific, so getting log events out even if DI configuration crashes is pretty useful.

I've been bitten by the app failing on startup, but how would you go about resolving this issue I brought up #620

glennc · 2017-05-25T19:31:17Z

@nblumhardt

as @epignosisx raised there are people who are already injecting services and using them with the logging system, I think we already have some other providers that need services today. Which we completely broke when we went the other way in preview1. Ideally we would provide a way to use services in DI without resorting to something like a service locator.
having providers in DI means that it is easy for various components to add providers and the composition and configuration model is well known and understood. This can be done either in program main or in ConfigureServices because it is understood how all the services compose and operate. Having as much of the stack as possible be configured and registered the same way is beneficial, as is the removal of special top-level APIs on WebHostBuilder.
we will log using EventSource before the container is built, though we discussed other things as well that are possible like a single log sink that can be set on the builder or something of that sort. You are right that this is a fundamental limitation of the design. Today we log very little before the container is built, in fact I don't think we log anything. But we would use EventSource as we added logging. For logging that an app dev wants to use they can also presumably configure Serilog statically in program main and log to Serilog directly there, registering the provider for the rest of their app. Right? Just thinking "out loud" on that last bit.

There are also some questions about how you can use logging outside of ASP.NET Core, like with EF in a UWP application, that we need to consider.

nblumhardt · 2017-05-25T21:58:47Z

Thanks for the follow-ups @epignosisx @glennc.

they can also presumably configure Serilog statically in program main and log to Serilog directly there, registering the provider for the rest of their app. Right?

This is a good point, and I think it works if you use Serilog. From the perspective of the library as a whole it still seems like there should be a way for developers to get start-up errors through their logging pipeline using only MEL. Having to go to a separate collection point does leaves the problem on the end-user developer's plate, it would seem.

#620 is an interesting problem; there are ways around it by using static state (put the IHttpContextAccessor in some well-known location when it becomes available, and have the enricher look for it there). Not ideal, but might be preferable to tangling up DI and logging inextricably.

I wish I could add more useful ideas here - it's a challenging API to get right! :-)

khellang · 2017-05-26T21:32:38Z

src/Microsoft.Extensions.Logging/LoggingServiceCollectionExtensions.cs

+        /// <param name="services">The <see cref="IServiceCollection" /> to add services to.</param>
+        /// <param name="configure">The <see cref="ILoggerBuilder"/> configuration delegate.</param>
+        /// <returns>The <see cref="IServiceCollection"/> so that additional calls can be chained.</returns>
+        public static IServiceCollection AddLogging(this IServiceCollection services, Action<ILoggerBuilder> configure)


😍😍😍

BrennanConroy · 2017-05-26T17:02:05Z

src/Microsoft.Extensions.Logging.AzureAppServices/AzureAppServicesLoggerFactoryExtensions.cs

        {
            if (WebAppContext.Default.IsRunningInAzureWebApp)
            {
                // Only add the provider if we're in Azure WebApp. That cannot change once the apps started
-                factory.AddProvider("AzureAppServices", new AzureAppServicesDiagnosticsLoggerProvider(WebAppContext.Default, settings));
+                builder.Services.AddSingleton(WebAppContext.Default);


Do we need to add this to DI if we pass a singleton instance of AzureAppServicesDiagnosticsLoggerProvider with WebAppContext.Default already in it?

BrennanConroy · 2017-05-26T17:03:13Z

src/Microsoft.Extensions.Logging.Console/ConfigurationConsoleLoggerConfigureOptions.cs

+
+namespace Microsoft.Extensions.Logging.Console
+{
+    public class ConfigurationConsoleLoggerConfigureOptions : ConfigureOptions<ConsoleLoggerOptions>


This name is a bit much?

I need suggestions :)

ConfigureConsole[Logger]Options?

BrennanConroy · 2017-05-26T17:12:09Z

src/Microsoft.Extensions.Logging.Console/ConsoleLoggerProvider.cs

            {
-                _settings = new ConsoleLoggerSettings();
+                logger.Filter = GetFilter(logger.Name, _settings);


I think this can be removed, _settings is only used for 1.X ConsoleLogger methods

BrennanConroy · 2017-05-26T17:44:36Z

src/Microsoft.Extensions.Logging/ConfigurationLoggerFilterConfigureOptions.cs

+        {
+            foreach (var section in configurationSection.AsEnumerable(true))
+            {
+                if (TryGetSwitch(section.Value, out var level))


Where would the error propagate to for an invalid config value?

Whoever tries to inject ILogger first would get it.

BrennanConroy · 2017-05-26T17:47:54Z

src/Microsoft.Extensions.Logging/FilterLoggerBuilderExtensions.cs

+
+        public static ILoggerBuilder AddFilter(this ILoggerBuilder builder, Func<string, string, LogLevel, bool> filter)
+        {
+            return AddRule(builder, new LoggerFilterRule(null, null, null, filter));


I think adding named parameters would be useful here for readability. (Here = all of the new LoggerFilterRule(...) calls)

BrennanConroy · 2017-05-26T17:57:31Z

src/Microsoft.Extensions.Logging/Logger.cs

-
-                // checks config and filters set on the LoggerFactory
-                if (!_loggerFactory.IsEnabled(loggerInfo.ProviderNames, _categoryName, logLevel))
+                if (!loggerInfo.IsEnabled(logLevel))


This function is supposed to check if at least 1 logger is enabled, and if 1 is found you can return true immediately. Currently you are checking if any are not enabled and returning false.

BrennanConroy · 2017-05-26T17:59:01Z

src/Microsoft.Extensions.Logging/LoggerBuilder.cs

@@ -0,0 +1,17 @@
+// Copyright (c) .NET Foundation. All rights reserved.


Should probably move this into an internal folder

BrennanConroy · 2017-05-26T21:59:30Z

src/Microsoft.Extensions.Logging/LoggerFactory.cs

-            }
-
-            AddProvider(name, provider);
+            _providerRegistrations = providers.Select(provider => new ProviderRegistration { Provider = provider}).ToList();


nit: space after provider

BrennanConroy · 2017-05-26T22:13:51Z

src/Microsoft.Extensions.Logging/LoggerRuleSelector.cs

+// Filter rule selection:
+            // 1. Select rules for current logger type, if there is none, select ones without logger type specified
+            // 2. Select rules with longest matching categories
+            // 3. If there no category


Something doesn't look right here.

BrennanConroy · 2017-05-26T22:42:28Z

src/Microsoft.Extensions.Logging/FilterLoggerBuilderExtensions.cs

+        public static ILoggerBuilder AddFilter(this ILoggerBuilder builder, Func<string, string, LogLevel, bool> filter)
+        {
+            return AddRule(builder, new LoggerFilterRule(null, null, null, filter));
+        }


nit: newline

BrennanConroy · 2017-05-30T19:02:41Z

src/Microsoft.Extensions.Logging.Abstractions/ILoggerFactory.cs

        /// Adds an <see cref="ILoggerProvider"/> to the logging system.
        /// </summary>
        /// <param name="provider">The <see cref="ILoggerProvider"/>.</param>
-        [Obsolete("This method is obsolete and will be removed in a future version. The recommended alternative is to call the Microsoft.Extensions.Logging.AddProvider() method on the Microsoft.Extensions.Logging.LoggerFactory instance.")]


Did we decide to un-obsolete everything?

Yep, EF uses AddProvider and there is no time to fix it there.

Obsolete doesn't mean it wont work, calling AddProvider should still be fine they just have to ignore the warning.

Issues is there is no "right" way for them to do it right now, so showing obsolete warning is not entirely correct.

analogrelay · 2017-05-30T19:18:44Z

src/Microsoft.Extensions.Logging/LoggerBuilder.cs

+
+namespace Microsoft.Extensions.Logging
+{
+    internal class LoggerBuilder : ILoggerBuilder


How do we decide? Other .Logging stuff was internal.

If we want to preserve the ability to new this up without an explicit service collection then it should be public and have a parameters less ctor that news up a service collection internally. But meh.

analogrelay · 2017-05-30T19:20:04Z

src/Microsoft.Extensions.Logging/LoggerRuleSelector.cs

+            // Filter rule selection:
+            // 1. Select rules for current logger type, if there is none, select ones without logger type specified
+            // 2. Select rules with longest matching categories
+            // 3. If there no category


Did you forget to

pakrym · 2017-05-30T23:27:07Z

🆙📅 I'd like to get it merged tomorrow

cwe1ss · 2017-05-31T11:32:25Z

src/Microsoft.Extensions.Logging/LoggerBuilderExtensions.cs

+        public static ILoggerBuilder AddConfiguration(this ILoggerBuilder builder, IConfiguration configuration)
+        {
+            builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton<IConfigureOptions<LoggerFilterOptions>>(new LoggerFilterConfigureOptions(configuration)));
+            builder.Services.TryAddEnumerable(ServiceDescriptor.Singleton<IOptionsChangeTokenSource<LoggerFilterOptions>>(new ConfigurationChangeTokenSource<LoggerFilterOptions>(configuration)));


Does the "TryAddEnumerable" mean that calling AddConfiguration a second time with a different configuration source is a no-op? If so, there would be quite a mix of behaviors here (IIUC):

AddConfiguration can only be called once and further calls are ignored

AddProvider can be called multiple times - the same provider can even be added multiple times

SetMinimumLevel can be called multiple times and overwrites previous values

Not sure if it's a valid scenario to call "AddConfiguration" with different configuration sources but would it be a problem if it were allowed? The IConfigureOptions system can handle this anyway, right?

cwe1ss · 2017-05-31T11:38:43Z

src/Microsoft.Extensions.Logging/LoggingServiceCollectionExtensions.cs

+        /// <param name="services">The <see cref="IServiceCollection" /> to add services to.</param>
+        /// <param name="configure">The <see cref="ILoggerBuilder"/> configuration delegate.</param>
+        /// <returns>The <see cref="IServiceCollection"/> so that additional calls can be chained.</returns>
+        public static IServiceCollection AddLogging(this IServiceCollection services, Action<ILoggerBuilder> configure)


Nitpick: Wouldn't ILoggingBuilder be better since the "Logging" module is configured with it and not a single logger. (just a suggestion/question, probably really not important)

cwe1ss · 2017-05-31T11:42:22Z

src/Microsoft.Extensions.Logging/Microsoft.Extensions.Logging.csproj

@@ -17,6 +17,8 @@
  <ItemGroup>
    <PackageReference Include="Microsoft.Extensions.Configuration" Version="$(AspNetCoreVersion)" />
    <PackageReference Include="Microsoft.Extensions.DependencyInjection.Abstractions" Version="$(AspNetCoreVersion)" />
+    <PackageReference Include="Microsoft.Extensions.Options" Version="$(AspNetCoreVersion)" />
+    <PackageReference Include="Microsoft.Extensions.Options.ConfigurationExtensions" Version="$(AspNetCoreVersion)" />


"M.E.O.ConfigurationExtensions" brings in some of the above as transitive dependencies. I think it's more declarative to have those here as well - but not sure how you handle these things?!?

These dependencies do kinda suck. Should we have a logging.configuration package?

I think the most important thing is for M.E.L.Abstractions to be clean because that's what libraries will depend on. M.E.L will be used by hosts and they have all of these dependencies anyway, so it's probably not necessary to split this?!

@davidfowl it should align with our IDefaultConfigureOptions story

cwe1ss · 2017-05-31T12:00:56Z

src/Microsoft.Extensions.Logging.Console/ConsoleLoggerFactoryExtensions.cs

+        /// <summary>
+        /// Adds a console logger named 'Console' to the factory.
+        /// </summary>
+        /// <param name="builder">The <see cref="LoggerFactory"/> to use.</param>


The <see cref="LoggerFactory"/> to use. is no longer a good comment here, is it? (applies to all of the ILoggerBuilder based methods)

Provider aliases support

Use ProviderAliasAttribute Fix ProviderAliasAttribute usage rules

cwe1ss · 2017-05-31T19:18:29Z

Regarding the general issue of logging crashes before/on DI: We also tried to setup the whole logging system in program.cs before the WebHost is built. However we ended up still needing the environment name, some configuration values etc - so we would have duplicated a lot of WebHostBuilder logic and gave up in the end.

One thing that should still be possible though is to create your own mini DI-provider just for logging in Program.Main and use this one to catch startup exceptions (with CaptureStartupErrors=false). This one could then be environment-independent and log everything to e.g. Console/EventLog.

I'm also not really a friend of EventSource/ETW. It sounds great in theory but it's yet another thing to deal with and gets quite complex on Azure (ARM template -> Azure Diagnostics agent -> Azure Tables -> OMS). The new EventFlow library might help here but I haven't looked into it much yet.

BrennanConroy · 2017-05-31T23:16:33Z

src/Microsoft.Extensions.Logging.Testing/AssemblyTestLog.cs

-            }
+                if (output != null)
+                {
+                    builder.AddXunit(output, LogLevel.Debug);


Should we add a provider name to the XunitLoggerProvider?

dnfclas added the cla-already-signed label May 24, 2017

nblumhardt reviewed May 24, 2017

View reviewed changes

pakrym changed the title ~~[WIP] Logging in DI~~ Logging in DI May 25, 2017

pakrym requested review from Tratcher, JunTaoLuo, BrennanConroy and analogrelay May 25, 2017 21:53

khellang reviewed May 26, 2017

View reviewed changes

BrennanConroy reviewed May 26, 2017

View reviewed changes

BrennanConroy reviewed May 30, 2017

View reviewed changes

analogrelay reviewed May 30, 2017

View reviewed changes

pakrym added 8 commits May 30, 2017 16:58

Logging in DI

b0d9e28

All things in the world

3aaa06d

ILoggerBuilder all the things

7654420

All tests

1571100

Fix tests for real this time

00a9b5f

Move AddProvider to main lib

baf6c72

More fixes

4b73609

Add abstraction

dd49a17

pakrym added 9 commits May 30, 2017 16:58

Nits and (c)

34414f9

Logger builder delegate

0920735

Less overloads

ba88967

More overloads less obsoletes

5bfc385

Minimum and use last filter

d699b31

Some PR feedback

9f3d9f5

Internal, comments, tests.

f8bf9ce

Shorten class name

b5f8d22

ApiCheck

027db2b

pakrym force-pushed the pakrym/logging-spike branch from b7b3e58 to 027db2b Compare May 30, 2017 23:58

cwe1ss reviewed May 31, 2017

View reviewed changes

pakrym added 3 commits May 31, 2017 09:24

ILoggingBuilder

f84a45a

No alloc rule matching

12cf600

Provider aliases support

Uncomment tests

4bc4987

Use ProviderAliasAttribute Fix ProviderAliasAttribute usage rules

BrennanConroy reviewed May 31, 2017

View reviewed changes

BrennanConroy approved these changes May 31, 2017

View reviewed changes

pakrym changed the base branch from dev to rel/2.0.0-preview2 June 2, 2017 15:28

pakrym merged commit 355b186 into rel/2.0.0-preview2 Jun 2, 2017

This was referenced Jun 5, 2017

Provide way to have DI services participate in the logger configuration (broken with 2.0 changes) #620

Closed

Default log levels #618

Closed

cwe1ss mentioned this pull request Jun 8, 2017

Consider reacting to Microsoft.Extensions.Logging changes microsoft/ApplicationInsights-aspnetcore#466

Closed

pakrym mentioned this pull request Jun 14, 2017

loggerFactory.WithFilters doesn't work as expected #525

Closed

pakrym mentioned this pull request Jun 22, 2017

Configuring logging from appSettings.json #437

Closed

poke mentioned this pull request Jun 29, 2017

NET Core 2.0.0-preview2 Log filtering #654

Closed

Aurel mentioned this pull request Aug 2, 2017

Unable to create ILogger that only exists in specific IServiceScope #678

Closed

natemcmaster deleted the pakrym/logging-spike branch November 6, 2018 22:42

		@@ -0,0 +1,17 @@
		// Copyright (c) .NET Foundation. All rights reserved.

Logging in DI #626

Logging in DI #626

Conversation

pakrym commented May 24, 2017 • edited by DamianEdwards Loading

pakrym commented May 24, 2017

davidfowl commented May 24, 2017

pakrym commented May 24, 2017

khellang commented May 24, 2017 • edited Loading

pakrym commented May 24, 2017

khellang commented May 24, 2017 • edited Loading

nblumhardt left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nblumhardt commented May 24, 2017

epignosisx commented May 25, 2017

glennc commented May 25, 2017

nblumhardt commented May 25, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pakrym commented May 30, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cwe1ss commented May 31, 2017

Choose a reason for hiding this comment

pakrym commented May 24, 2017 •

edited by DamianEdwards

Loading

khellang commented May 24, 2017 •

edited

Loading

khellang commented May 24, 2017 •

edited

Loading

nblumhardt commented May 25, 2017 •

edited

Loading