Search code examples
c#loggingmauinlog

Why is NLog WriteToNil not filtering out the specified loggers?

I'm using NLog in a .Net MAUI app as per the instructions here: https://github.com/NLog/NLog.Targets.MauiLog

The logging is setup fine, no problem there. However, I want to filter out some verbose 3rd-party / Microsoft components. I followed the instructions here to do that: https://github.com/NLog/NLog/wiki/Fluent-Configuration-API (see section Build NLog config that restricts output from noisy logger). However, whatever I do, the filter is not working :(

Here is my configuration:

var logger = NLog.LogManager.Setup().RegisterMauiLog()
    .LoadConfiguration(builder =>
    {
        SimpleLayout layout = new SimpleLayout("${date:format=yyyy-MM-dd HH\\:mm\\:ss} ${uppercase:${level}} ${logger}: ${message} ${exception:format=tostring}");
        SimpleLayout filename = new SimpleLayout(Path.Combine(FileSystem.Current.AppDataDirectory, "Logs", "Log.log"));

        builder.ForLogger("Microsoft.AspNetCore.Components.*").WriteToNil(NLog.LogLevel.Warn);
        builder.ForLogger("Microsoft.EntityFrameworkCore.Database.Connection").WriteToNil(NLog.LogLevel.Warn);
        builder.ForLogger(NLog.LogLevel.Debug).WriteToFile(filename, layout, Encoding.UTF8, NLog.Targets.LineEndingMode.Default, true, false, 1048576, 3, 5);
        builder.ForLogger(NLog.LogLevel.Debug).WriteToMauiLog(layout);
        
        NLog.Common.InternalLogger.LogFile = Path.Combine(FileSystem.Current.AppDataDirectory, "Logs", "NLog-log.log");
        NLog.Common.InternalLogger.LogLevel = NLog.LogLevel.Debug;
        NLog.LogManager.GetLogger("Test").Info("Hello World");
    })
    .GetCurrentClassLogger();

This config produced the following output in the NLog internal log file:

2023-12-19 19:26:09.4116 Debug logNamePattern: (Microsoft.AspNetCore.Components.:StartsWith) levels: [ Warn Error Fatal ] writeTo: [ ]
2023-12-19 19:26:09.4116 Debug logNamePattern: (Microsoft.EntityFrameworkCore.Database.Connection:Equals) levels: [ Warn Error Fatal ] writeTo: [ ]
2023-12-19 19:26:09.4116 Debug logNamePattern: (:All) levels: [ Debug Info Warn Error Fatal ] writeTo: [ File ]
2023-12-19 19:26:09.4116 Debug logNamePattern: (:All) levels: [ Debug Info Warn Error Fatal ] writeTo: [ MauiLog ]

This looked to me like it was only filtering levels above WARN for the loggers that I wanted to filter out (despite the WriteToNil arguments seeming to say that they filter everything below the provided level, WARN in my case). So, I tried it the other way round:

var logger = NLog.LogManager.Setup().RegisterMauiLog()
    .LoadConfiguration(builder =>
    {
        SimpleLayout layout = new SimpleLayout("${date:format=yyyy-MM-dd HH\\:mm\\:ss} ${uppercase:${level}} ${logger}: ${message} ${exception:format=tostring}");
        SimpleLayout filename = new SimpleLayout(Path.Combine(FileSystem.Current.AppDataDirectory, "Logs", "Log.log"));

        builder.ForLogger("Microsoft.AspNetCore.Components.*").WriteToNil(NLog.LogLevel.Debug);
        builder.ForLogger("Microsoft.EntityFrameworkCore.Database.Connection").WriteToNil(NLog.LogLevel.Debug);
        builder.ForLogger(NLog.LogLevel.Debug).WriteToFile(filename, layout, Encoding.UTF8, NLog.Targets.LineEndingMode.Default, true, false, 1048576, 3, 5);
        builder.ForLogger(NLog.LogLevel.Debug).WriteToMauiLog(layout);        
        
        NLog.Common.InternalLogger.LogFile = Path.Combine(FileSystem.Current.AppDataDirectory, "Logs", "NLog-log.log");
        NLog.Common.InternalLogger.LogLevel = NLog.LogLevel.Debug;
        NLog.LogManager.GetLogger("Test").Info("Hello World");
    })
    .GetCurrentClassLogger();

This config produced the following output in the NLog internal log file:

2023-12-19 19:27:59.8683 Debug logNamePattern: (Microsoft.AspNetCore.Components.:StartsWith) levels: [ Debug Info Warn Error Fatal ] writeTo: [ ]
2023-12-19 19:27:59.8683 Debug logNamePattern: (Microsoft.EntityFrameworkCore.Database.Connection:Equals) levels: [ Debug Info Warn Error Fatal ] writeTo: [ ]
2023-12-19 19:27:59.8683 Debug logNamePattern: (:All) levels: [ Debug Info Warn Error Fatal ] writeTo: [ File ]
2023-12-19 19:27:59.8683 Debug logNamePattern: (:All) levels: [ Debug Info Warn Error Fatal ] writeTo: [ MauiLog ]

This looked like it was going to filter out all levels for the loggers I was trying to get rid of, more hopeful, but alas I am still getting the non-desired loggers in my log :( For example:

2023-12-19 19:26:12.5523 Debug Targets configured when LogLevel >= Debug for Logger: Microsoft.EntityFrameworkCore.Database.Connection
2023-12-19 19:26:12.5523 Debug Logger Microsoft.EntityFrameworkCore.Database.Connection [Debug] => File MauiLog
2023-12-19 19:26:12.5523 Debug Logger Microsoft.EntityFrameworkCore.Database.Connection [Info] => File MauiLog
2023-12-19 19:26:12.5523 Debug Logger Microsoft.EntityFrameworkCore.Database.Connection [Warn] => File MauiLog
2023-12-19 19:26:12.5523 Debug Logger Microsoft.EntityFrameworkCore.Database.Connection [Error] => File MauiLog
2023-12-19 19:26:12.5523 Debug Logger Microsoft.EntityFrameworkCore.Database.Connection [Fatal] => File MauiLog

Finally I thought I'd try registering the loggers in a different order:

var logger = NLog.LogManager.Setup().RegisterMauiLog()
    .LoadConfiguration(builder =>
    {
        SimpleLayout layout = new SimpleLayout("${date:format=yyyy-MM-dd HH\\:mm\\:ss} ${uppercase:${level}} ${logger}: ${message} ${exception:format=tostring}");
        SimpleLayout filename = new SimpleLayout(Path.Combine(FileSystem.Current.AppDataDirectory, "Logs", "Log.log"));

        builder.ForLogger(NLog.LogLevel.Debug).WriteToFile(filename, layout, Encoding.UTF8, NLog.Targets.LineEndingMode.Default, true, false, 1048576, 3, 5);
        builder.ForLogger(NLog.LogLevel.Debug).WriteToMauiLog(layout);
        builder.ForLogger("Microsoft.AspNetCore.Components.*").WriteToNil(NLog.LogLevel.Debug);
        builder.ForLogger("Microsoft.EntityFrameworkCore.Database.Connection").WriteToNil(NLog.LogLevel.Debug);
        
        NLog.Common.InternalLogger.LogFile = Path.Combine(FileSystem.Current.AppDataDirectory, "Logs", "NLog-log.log");
        NLog.Common.InternalLogger.LogLevel = NLog.LogLevel.Debug;
        NLog.LogManager.GetLogger("Test").Info("Hello World");
    })
    .GetCurrentClassLogger();

Which looks like this in the internal log:

2023-12-19 19:37:20.4908 Debug logNamePattern: (:All) levels: [ Debug Info Warn Error Fatal ] writeTo: [ File ]
2023-12-19 19:37:20.4908 Debug logNamePattern: (:All) levels: [ Debug Info Warn Error Fatal ] writeTo: [ MauiLog ]
2023-12-19 19:37:20.4908 Debug logNamePattern: (Microsoft.AspNetCore.Components.:StartsWith) levels: [ Debug Info Warn Error Fatal ] writeTo: [ ]
2023-12-19 19:37:20.4908 Debug logNamePattern: (Microsoft.EntityFrameworkCore.Database.Connection:Equals) levels: [ Debug Info Warn Error Fatal ] writeTo: [ ]

But, I'm still getting the unwanted loggers in the log :(

At this point I'm at a bit of a loss to know what to do next. AHA!

Solution

  • Thank you for reporting that NLog v5.2.7 fails to report the expected LoggingRule-configuration when using WriteToNil, FinalMinLevel or Final.

    NLog v5.2.8 has been released includes pull-request that improves NLog InternalLogger output when using FinalMinLevel, and fixes the unexpected behavior by ForLogger(NLog.LogLevel.Debug). Until having updated to the latest NLog-version, then ForLogger().FilterMinLevel(NLog.LogLevel.Debug) can be used as work-around. Thus your initial configuration:

    var logger = NLog.LogManager.Setup().RegisterMauiLog()
    .LoadConfiguration(builder =>
    {
        SimpleLayout layout = new SimpleLayout("${date:format=yyyy-MM-dd HH\\:mm\\:ss} ${uppercase:${level}} ${logger}: ${message} ${exception:format=tostring}");
        SimpleLayout filename = new SimpleLayout(Path.Combine(FileSystem.Current.AppDataDirectory, "Logs", "Log.log"));

        builder.ForLogger("Microsoft.AspNetCore.Components.*").WriteToNil(NLog.LogLevel.Warn);
        builder.ForLogger("Microsoft.EntityFrameworkCore.Database.Connection").WriteToNil(NLog.LogLevel.Warn);
        builder.ForLogger().FilterMinLevel(NLog.LogLevel.Debug).WriteToFile(filename, layout, Encoding.UTF8, NLog.Targets.LineEndingMode.Default, true, false, 1048576, 3, 5);
        builder.ForLogger().FilterMinLevel(NLog.LogLevel.Debug).WriteToMauiLog(layout);        
    })
    .GetCurrentClassLogger();

    Will give the new output where LoggingRules created with WriteToNil, will show that LogLevels with lower severity will writeTo empty target-list.

    logNamePattern: (Microsoft.AspNetCore.Components.:StartsWith) levels: [ Trace Debug Info ] writeTo: [ ] finalMinLevel: Warn
logNamePattern: (Microsoft.EntityFrameworkCore.Database.Connection:Equals) levels: [ Trace Debug Info ] writeTo: [ ] finalMinLevel: Warn
logNamePattern: (:All) levels: [ Debug Info Warn Error Fatal ] writeTo: [ File ]
logNamePattern: (:All) levels: [ Debug Info Warn Error Fatal ] writeTo: [ MauiLog ]

    And for a Logger with name Microsoft.EntityFrameworkCore.Database.Connection:

    Targets configured when LogLevel >= Debug for Logger: Microsoft.EntityFrameworkCore.Database.Connection
Logger Microsoft.EntityFrameworkCore.Database.Connection [Warn] => File MauiLog
Logger Microsoft.EntityFrameworkCore.Database.Connection [Error] => File MauiLog
Logger Microsoft.EntityFrameworkCore.Database.Connection [Fatal] => File MauiLog