Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

How does overriding rules in appsettings.json work? #472

Closed
lorenh opened this issue Feb 4, 2021 · 13 comments
Closed

How does overriding rules in appsettings.json work? #472

lorenh opened this issue Feb 4, 2021 · 13 comments
Labels

Comments

@lorenh
Copy link

lorenh commented Feb 4, 2021

Type: Question
NLog version: 4.7.6
NLog.Extensions.Logging version: 1.7.0
NLog.Web.AspNetCore version: 4.10.0
Platform: ..NET Core 5.0

I am trying to figure out how to override rules in appsetting.json as outlined here https://github.com/NLog/NLog.Extensions.Logging/wiki/NLog-configuration-with-appsettings.json#logging-rule-override and can't seem to figure it out.

I was hoping to override the minLevel of Info on the 000_RoutingController rule to be a minLevel of Trace when running with ASPNETCORE_ENVIRONMENT = Development. Yet it remains Info. What am I doing wrong?

-- appsettings.json --

{
  "NLog": {
:
    "rules": {
      "000_RoutingController": {
        "logger": "RoutingController",
        "minLevel": "Info",
        "writeTo": "logfile",
        "final": true
      },
      "010_Microsoft.Hosting.Lifetime": {
        "logger": "Microsoft.Hosting.Lifetime",
        "minLevel": "Info",
        "writeTo": "logfile",
        "final": true
      },
      "020_Microsoft": {
        "logger": "Microsoft.*",
        "minLevel": "Warn",
        "writeTo": "logfile"
      },
      "021_Microsoft": {
        "logger": "Microsoft.*",
        "final": true
      },
      "999_EverythingElse": {
        "logger": "*",
        "minLevel": "Info",
        "writeTo": "logfile"
      }
    }
  }
}

-- appsettings.Development.json --

{
  "NLog": {
:
    "rules": {
      "000_RoutingController": {
        "logger": "RoutingController",
        "minLevel": "Trace",
        "writeTo": "logfile",
        "final": true
      },
      "999_EverythingElse": {
        "logger": "*",
        "minLevel": "Debug",
        "writeTo": "logfile"
      }
    }
  }
}
@snakefoot
Copy link
Contributor

snakefoot commented Feb 4, 2021

Does your appsettings.json (or appsettings.Development.json) include any filtering in the Microsoft-Extension-Logging-section:

https://github.com/NLog/NLog.Web/wiki/Missing-trace%5Cdebug-logs-in-ASP.NET-Core-5%3F

@lorenh
Copy link
Author

lorenh commented Feb 4, 2021

It does not. I had noticed how the two logging systems can conflict in some other posts and completely removed all microsoft logging settings to make sure I was dealing just with NLog

Here's the full appsetting.json.

{
  "NLog": {
    "autoReload": true,
    "throwConfigExceptions": true,
    "internalLogLevel": "Warn",
    "internalLogFile": "${basedir}/log/routing-nlog-internal.log",
    "extensions": [
      { "assembly": "NLog.Extensions.Logging" },
      { "assembly": "NLog.Web.AspNetCore" }
    ],
    "variables": {
      "var_logdir": "${basedir}/log"
    },
    "targets": {
      "logfile": {
        "type": "File",
        "fileName": "${var_logdir}/routing.log",
        "layout": "${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url=${aspnet-request-url}|action=${aspnet-mvc-action}",
        "maxArchiveDays": 2,
        "archiveAboveSize": 1000000000,
        "archiveFileName": "${var_logdir}/routing.{#}.log",
        "archiveEvery": "Day",
        "archiveNumbering": "DateAndSequence",
        "archiveDateFormat": "yyyyMMdd"
      },
      "logconsole": {
        "type": "Console"
      }
    },
    "rules": {
      "000_RoutingController": {
        "logger": "RoutingController",
        "minLevel": "Trace",
        "writeTo": "logfile",
        "final": true
      },
      "010_Microsoft.Hosting.Lifetime": {
        "logger": "Microsoft.Hosting.Lifetime",
        "minLevel": "Info",
        "writeTo": "logfile",
        "final": true
      },
      "020_Microsoft": {
        "logger": "Microsoft.*",
        "minLevel": "Warn",
        "writeTo": "logfile"
      },
      "021_Microsoft": {
        "logger": "Microsoft.*",
        "final": true
      },
      "999_EverythingElse": {
        "logger": "*",
        "minLevel": "Info",
        "writeTo": "logfile"
      }
    }
  }
}

@snakefoot
Copy link
Contributor

snakefoot commented Feb 5, 2021

It is not easy to be a good citizin in the Microsoft Extension Logging LoggerFactory. Because even without any configuration, then its default values still applies. What happens if you try this (Adding setup of "Default": "Trace" in your appsettings.json and appsettings.Development.json)

{
  "Logging": {
    "LogLevel": {
      "Default": "Trace"
    }
  },
  "NLog": {
    "autoReload": true,
    "throwConfigExceptions": true,
    "internalLogLevel": "Warn",
    "internalLogFile": "${basedir}/log/routing-nlog-internal.log",
    "extensions": [
      { "assembly": "NLog.Extensions.Logging" },
      { "assembly": "NLog.Web.AspNetCore" }
    ],
    "variables": {
      "var_logdir": "${basedir}/log"
    },
    "targets": {
      "logfile": {
        "type": "File",
        "fileName": "${var_logdir}/routing.log",
        "layout": "${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url=${aspnet-request-url}|action=${aspnet-mvc-action}",
        "maxArchiveDays": 2,
        "archiveAboveSize": 1000000000,
        "archiveFileName": "${var_logdir}/routing.{#}.log",
        "archiveEvery": "Day",
        "archiveNumbering": "DateAndSequence",
        "archiveDateFormat": "yyyyMMdd"
      },
      "logconsole": {
        "type": "Console"
      }
    },
    "rules": {
      "000_RoutingController": {
        "logger": "RoutingController",
        "minLevel": "Trace",
        "writeTo": "logfile",
        "final": true
      },
      "010_Microsoft.Hosting.Lifetime": {
        "logger": "Microsoft.Hosting.Lifetime",
        "minLevel": "Info",
        "writeTo": "logfile",
        "final": true
      },
      "020_Microsoft": {
        "logger": "Microsoft.*",
        "minLevel": "Warn",
        "writeTo": "logfile"
      },
      "021_Microsoft": {
        "logger": "Microsoft.*",
        "final": true
      },
      "999_EverythingElse": {
        "logger": "*",
        "minLevel": "Info",
        "writeTo": "logfile"
      }
    }
  }
}

I guess one could add an option to NLog, so it will take over everything and not allow other citizens in the LoggerFactory-city. Could you share the code where you setup NLog with Microsoft-Extension-Logging?

@lorenh
Copy link
Author

lorenh commented Feb 5, 2021

No joy. I tried adding the MEL section with Trace in appsettings.json and in appsettings.Development.json, and the routing controller is still "Info" when running in Development. How is everyone else using this json-based configuration to override settings per environment?

{
  "Logging": {
    "LogLevel": {
      "Default": "Trace"
    }
  },
  "NLog": {
    "autoReload": true,
    "throwConfigExceptions": true,
    "internalLogLevel": "Warn",
    "internalLogFile": "${basedir}/log/routing-nlog-internal.log",
    "extensions": [
      { "assembly": "NLog.Extensions.Logging" },
      { "assembly": "NLog.Web.AspNetCore" }
    ],
    "variables": {
      "var_logdir": "${basedir}/log"
    },
    "targets": {
      "logfile": {
        "type": "File",
        "fileName": "${var_logdir}/routing.log",
        "layout": "${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url=${aspnet-request-url}|action=${aspnet-mvc-action}",
        "maxArchiveDays": 2,
        "archiveAboveSize": 1000000000,
        "archiveFileName": "${var_logdir}/routing.{#}.log",
        "archiveEvery": "Day",
        "archiveNumbering": "DateAndSequence",
        "archiveDateFormat": "yyyyMMdd"
      },
      "logconsole": {
        "type": "Console"
      }
    },
    "rules": {
      "000_RoutingController": {
        "logger": "RoutingController",
        "minLevel": "Info",
        "writeTo": "logfile",
        "final": true
      },
      "010_Microsoft.Hosting.Lifetime": {
        "logger": "Microsoft.Hosting.Lifetime",
        "minLevel": "Info",
        "writeTo": "logfile",
        "final": true
      },
      "020_Microsoft": {
        "logger": "Microsoft.*",
        "minLevel": "Warn",
        "writeTo": "logfile"
      },
      "021_Microsoft": {
        "logger": "Microsoft.*",
        "final": true
      },
      "999_EverythingElse": {
        "logger": "*",
        "minLevel": "Info",
        "writeTo": "logfile"
      }
    }
  },
  "AllowedHosts": "*"
}
{
  "Logging": {
    "LogLevel": {
      "Default": "Trace"
    }
  },
  "NLog": {
    "rules": {
      "000_RoutingController": {
        "logger": "RoutingController",
        "minLevel": "Trace",
        "writeTo": "logfile",
        "final": true
      },
      "999_EverythingElse": {
        "logger": "*",
        "minLevel": "Debug",
        "writeTo": "logfile"
      }
    }
  }
}

@snakefoot
Copy link
Contributor

snakefoot commented Feb 6, 2021

Just copy pasted your code into an example project and loaded it like this:

            var config = new ConfigurationBuilder()
                .SetBasePath(System.IO.Directory.GetCurrentDirectory())
                .AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)
                .AddJsonFile("appsettings.development.json", optional: true, reloadOnChange: true)
                .Build();

            var logger = LogManager.Setup()
                .LoadConfigurationFromSection(config)
                .GetLogger("RoutingController");

And the changes from appsettings.development.json applies without any issues. When ensuring to have configured "Copy if newer".

But I noticed that when building your own custom Microsoft LoggerFactory (instead of using the default factory-builders), then I had to do explicit specific call SetMinimumLevel (Since the vanilla Microsoft LoggerFactory doesn't automatically load from appsettings.json)

            var melFactory = LoggerFactory.Create(builder =>
            {
                builder.SetMinimumLevel(Microsoft.Extensions.Logging.LogLevel.Trace);
                builder.AddNLog();
            });
            var melLogger = melFactory.CreateLogger("RoutingController");

@lorenh
Copy link
Author

lorenh commented Feb 7, 2021

Here's how I am setting up Nlog, it looks different from yours. Is it true that you have to add all of the appsettings.{environment}.json files? Help me understand how this works. I want ASPNETCORE_ENVIRONMENT to control which environment specific override file to use, if I have 3 (appsettings.Development.json, appsettings.Staging.json, and appsettings.Production.json) do I have to add all 4 files in main?

        public static void Main(string[] args)
        {
            var config = new ConfigurationBuilder()
                .SetBasePath(System.IO.Directory.GetCurrentDirectory())
                .AddJsonFile("appsettings.json", optional: true, reloadOnChange: true).Build();
            LogManager.Configuration = new NLogLoggingConfiguration(config.GetSection("NLog"));

            var logger = NLogBuilder.ConfigureNLog(LogManager.Configuration).GetCurrentClassLogger();
            try
            {
                logger.Debug("Init main");
                CreateWebHostBuilder(args).Build().Run();
            }
            catch (Exception ex)
            {
                //NLog: catch setup errors
                logger.Error(ex, "Stopped program because of exception");
                throw;
            }
            finally
            {
                // Ensure to flush and stop internal timers/threads before application-exit (Avoid segmentation fault on Linux)
                NLog.LogManager.Shutdown();
            }
        }

Then later on in a different part of the application I am using an injected ILoggerFactory to create a logger like this:

var logger = loggerFactory.CreateLogger("RoutingController");
var traceEnabled = logger.IsEnabled(LogLevel.Trace);
var debugEnabled = logger.IsEnabled(LogLevel.Debug);

@snakefoot
Copy link
Contributor

snakefoot commented Feb 7, 2021

Since you are using NLog.Web.AspNetCore then you can do this:

            var logger = LogManager.Setup()
                                   .LoadConfigurationFromAppSettings()
                                   .GetCurrentClassLogger();

That can replace this (And it will automatically use ASPNETCORE_ENVIRONMENT):

            var config = new ConfigurationBuilder()
                .SetBasePath(System.IO.Directory.GetCurrentDirectory())
                .AddJsonFile("appsettings.json", optional: true, reloadOnChange: true).Build();
            LogManager.Configuration = new NLogLoggingConfiguration(config.GetSection("NLog"));

            var logger = NLogBuilder.ConfigureNLog(LogManager.Configuration).GetCurrentClassLogger();

See also: https://github.com/NLog/NLog.Web/blob/master/src/NLog.Web.AspNetCore/Config/SetupBuilderExtensions.cs

@lorenh
Copy link
Author

lorenh commented Feb 8, 2021

I switched to the LogManager.Setup() suggested above and it still wasn't working properly so I decided to try alternatives to NLog and tried Serilog instead and it dropped right in and worked right off first try. I really tried hard to stick with Nlog, but it just seemed like aspnetcore and Nlog didn't play nice together in this case.

@snakefoot
Copy link
Contributor

Sad that you were not able to make NLog work with your scenario. Unsure how to improve on this, since the examples presented by me, works on my machine. If you could attach an example of your last attempt before ditching NLog then I would be interested.

@lorenh
Copy link
Author

lorenh commented Feb 8, 2021

It probably has something to do with the way I am injecting one of the Microsoft interfaces: ILoggerFactory into a utility class and creating a logger using it with a string name I build instead of going through NLog's method of creating loggers.

var logger = loggerFactory.CreateLogger(controllerName.ToString() + "Controller");

This logger just didn't want to obey the NLog rules. Initializing using LogManager.Setup() in program.cs helped in some ways, but I just couldn't get my rule to override properly using the development json file.

@snakefoot
Copy link
Contributor

snakefoot commented Feb 8, 2021

The "problem" with NLog is that it tries to be a nice citizen in MEL-LoggerFactory. Where Serilog throws away the MEL-LoggerFactory and replaces it with its own. Guess this makes it simpler to use, than having to setup both MEL-LoggerFactory and NLog-LoggingProvider correctly.

Guess NLog should extend NLogProviderOptions with a new option to do the same replacement of MEL-LoggerFactory when calling AddNLog / UseNLog. See also: NLog/NLog.Web#235

@snakefoot
Copy link
Contributor

Closing the issue as works-as-designed. But could be a good idea to introduce an option called "ReplaceLoggerFactory", for cases like these.

@snakefoot
Copy link
Contributor

Pull-Request #482 has been created, that allows one to specify the option ReplaceLoggerFactory with NLog.Extensions.Logging ver. 1.7.2

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants