Home > Back-end >  NLog 5.0 - Filtering Microsoft.Extensions.Logging logs doesn't work
NLog 5.0 - Filtering Microsoft.Extensions.Logging logs doesn't work

Time:06-10

I've migrated an ASP.NET Core project from 3.1 to 6.0 and now I can't get rid of many Microsoft logs when using an Authentication middleware

For example, I always have those logs when I call my API endpoint having[Authorize(Roles = "admin")] annotation from an unauthorized client

2022-06-08 14:36:28.1023 INFO Microsoft.Extensions.Logging.LoggingExtensions.AuthenticationSchemeChallenged AuthenticationScheme: Bearer was challenged. 
2022-06-08 14:40:58.7025 INFO Microsoft.Extensions.Logging.LoggingExtensions.AuthenticationSchemeChallenged AuthenticationScheme: Bearer was challenged. 
2022-06-08 14:42:53.8049 INFO Microsoft.Extensions.Logging.LoggingExtensions.AuthenticationSchemeChallenged AuthenticationScheme: Bearer was challenged. 

I also have those logs when calling another API using a Refit Client

2022-06-07 13:38:35.6434 INFO Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler Log.RequestEnd Received HTTP response headers after 78.0306ms - 200
2022-06-07 13:38:35.6434 INFO Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler Log.RequestPipelineEnd End processing HTTP request after 81.3323ms - 200
2022-06-07 13:38:35.6947 INFO Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler Log.RequestPipelineStart Start processing HTTP request POST https://api.removed.com/endpoint
2022-06-07 13:38:35.6947 INFO Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler Log.RequestStart Sending HTTP request POST https://api.removed.com/endpoint
2022-06-07 13:38:35.8336 INFO Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler Log.RequestEnd Received HTTP response headers after 136.3691ms - 200
2022-06-07 13:38:35.8336 INFO Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler Log.RequestPipelineEnd End processing HTTP request after 139.7244ms - 200
2022-06-07 13:38:35.8418 INFO Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler Log.RequestStart Sending HTTP request POST https://api.removed.com/endpoint
2022-06-07 13:38:37.2229 INFO Microsoft.Extensions.Http.Logging.LoggingHttpMessageHandler Log.RequestEnd Received HTTP response headers after 1379.9163ms - 200
2022-06-07 13:38:37.2229 INFO Microsoft.Extensions.Http.Logging.LoggingScopeHttpMessageHandler Log.RequestPipelineEnd End processing HTTP request after 2437.5144ms - 200

Program.cs

using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Hosting;
using Microsoft.Extensions.Logging;
using NLog;
using NLog.Web;
using System;

namespace CDL_CloudServerApi
{
    public class Program
    {
        public static void Main(string[] args)
        {
            var logger = LogManager.Setup().LoadConfigurationFromAppSettings().GetCurrentClassLogger();

            try
            {
                logger.Debug("Create Host");
                CreateHostBuilder(args).Build().Run();
            }
            catch (Exception ex)
            {
                //NLog: catch setup errors
                logger.Error(ex, "Stopped program because of exception");
                throw;
            }
            finally
            {
                LogManager.Shutdown();
            }
        }

        public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .ConfigureLogging(logging =>
                {
                    logging.ClearProviders();
                    logging.SetMinimumLevel(Microsoft.Extensions.Logging.LogLevel.Warning);
                })
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder
                        .UseUrls("http://*:8282")
                        .UseStartup<Startup>()
                        .UseNLog();
                });
    }

}

nlog.config

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true"
      throwExceptions="false"
      internalLogLevel="Off" 
      internalLogFile="c:\temp\nlog-internal.log">

    <!-- enable asp.net core layout renderers -->
    <extensions>
        <add assembly="NLog.Web.AspNetCore"/>
    </extensions>

    <variable name="verbose" value="${longdate} ${uppercase:${level}} ${callsite:className=true:fileName=false:includeSourcePath=false:methodName=true:cleanNamesOfAnonymousDelegates=false:skipFrames=0} ${message}" />
    <variable name="verbose_inline" value="${replace:inner=${verbose}:searchFor=\\r\\n|\\n:replaceWith=->:regex=true} ${exception:format=toString,Data:maxInnerExceptionLevel=10}"/>

    <!-- 5GB max size per log-->
    <targets>
        <target name="logfile" xsi:type="File"
                fileName="${basedir}/log/logfile.txt"
                layout="${verbose_inline}"
                archiveFileName="${basedir}/log/archives/log.{#}.txt"
                archiveNumbering="Date"
                archiveDateFormat="yyyy-MM-dd"
                archiveEvery="Day"
                archiveAboveSize="5000000000"
                maxArchiveFiles="14"
                maxArchiveDays="7"
                concurrentWrites="true"
                keepFileOpen="false" />
    </targets>

    <rules>
        <!--Skip non-critical Microsoft logs and so log only own logs-->
        <logger name="Microsoft.*" finalMinLevel="Warn" />
        <logger name="System.Net.Http.*" finalMinLevel="Warn" />

        <logger name="*" minlevel="Info" writeTo="logfile" />
    </rules>
</nlog>

CodePudding user response:

You should include ${logger} in your layout, so you can see the logger-name that should be filtered away.

<variable name="verbose" value="${longdate} ${level:uppercase=true} ${logger} ${message}" />
<variable name="verbose_inline" value="${replace-newlines:replacement=->:${verbose}} ${exception:format=toString,Data}"/>

Alternative update to minLevel="Warn" for everything:

<logger name="*" minlevel="Warn" writeTo="logfile" />

Alternative specify RemoveLoggerFactoryFilter = false for NLogProviderOptions when calling UseNLog() as mentioned in NLog 5.0 - List of major changes. Then NLog will continue to follow Microsoft Logggng Filter-configuration.

Notice that you should be careful with ${callsite}, since it introduces a huge performance overhead.

Notice that ${replace-newlines} is faster than ${replace} with regex.

  • Related