ILogger not writing TRACE and DEBUG messages to target

Question

I'm working on setting up some logging in our ASP.NET Core 3 application, using ILogger (Microsoft.Extensions.Logging) with NLog to enable writing to text files.

The problem is, that the ILogger does not write TRACE and DEBUG level messages. Either to the text file nor the Visual Studio Output window. Using the NLog.Logger works with all levels. This issue also exists in a default ASP.NET Core 3 Web API application with NLog set up from their official tutorial. Following is the relevant code I have.

Program.cs

public static void Main(string[] args)
{
    var logger = NLog.Web.NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
    try
    {
        logger.Trace("NLog Trace from Main()");
        logger.Debug("NLog Debug from Main()");
        logger.Info("NLog Info from Main()");
        logger.Warn("NLog Warn from Main()");
        logger.Error("NLog Error from Main()");
        logger.Fatal("NLog Fatal from Main()");
        CreateHostBuilder(args).Build().Run();
    }
    catch (Exception exception)
    {
        //NLog: catch setup errors
        logger.Error(exception, "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();
    }
}

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .ConfigureWebHostDefaults(webBuilder =>
        {
            webBuilder.UseStartup<Startup>();
        })
        .ConfigureLogging(options =>
        {
            options.SetMinimumLevel(Microsoft.Extensions.Logging.LogLevel.Trace);
        }).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"
      internalLogLevel="Info"
      internalLogFile="c:\temp\internal-nlog.txt">

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

  <!-- the targets to write to -->
  <targets>
    <!-- write logs to file  -->
    <target xsi:type="File" name="allfile" fileName="c:\temp\nlog-all-${shortdate}.log"
            layout="${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}" />

    <!-- another file log, only own logs. Uses some ASP.NET core renderers -->
    <target xsi:type="File" name="ownFile-web" fileName="c:\temp\nlog-own-${shortdate}.log"
            layout="${longdate}|${event-properties:item=EventId_Id}|${uppercase:${level}}|${logger}|${message} ${exception:format=tostring}|url: ${aspnet-request-url}|action: ${aspnet-mvc-action}" />
  </targets>

  <!-- rules to map from logger name to target -->
  <rules>
    <!--All logs, including from Microsoft-->
    <logger name="*" minlevel="Trace" writeTo="allfile" />

    <!--Skip non-critical Microsoft logs and so log only own logs-->
    <logger name="Microsoft.*" maxlevel="Info" final="true" /> <!-- BlackHole without writeTo -->
    <logger name="*" minlevel="Trace" writeTo="ownFile-web" />
  </rules>
</nlog>

appsettings.json

{
  "Logging": {
    "LogLevel": {
      "Default": "Trace",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    }
  },
  "AllowedHosts": "*"
}

WeatherForecastController.cs

private readonly ILogger<WeatherForecastController> _logger;

public WeatherForecastController(ILogger<WeatherForecastController> logger)
{
    _logger = logger;
}

[HttpGet]
public IEnumerable<WeatherForecast> Get()
{
    _logger.LogTrace("ILogger LogTrace from WeatherForecastController.");
    _logger.LogDebug("ILogger LogDebug from WeatherForecastController.");
    _logger.LogInformation("ILogger LogInformation from WeatherForecastController.");
    _logger.LogWarning("ILogger LogWarning from WeatherForecastController.");
    _logger.LogError("ILogger LogError from WeatherForecastController.");
    _logger.LogCritical("ILogger LogCritical from WeatherForecastController.");
    var rng = new Random();
    return Enumerable.Range(1, 5).Select(index => new WeatherForecast
    {
        Date = DateTime.Now.AddDays(index),
        TemperatureC = rng.Next(-20, 55),
        Summary = Summaries[rng.Next(Summaries.Length)]
    })
    .ToArray();
}

Output in log file

2020-05-26 09:48:41.2752||TRACE|NLogTest.Program|NLog Trace from Main() |url: |action: 
2020-05-26 09:48:41.3081||DEBUG|NLogTest.Program|NLog Debug from Main() |url: |action: 
2020-05-26 09:48:41.3081||INFO|NLogTest.Program|NLog Info from Main() |url: |action: 
2020-05-26 09:48:41.3081||WARN|NLogTest.Program|NLog Warn from Main() |url: |action: 
2020-05-26 09:48:41.3081||ERROR|NLogTest.Program|NLog Error from Main() |url: |action: 
2020-05-26 09:48:41.3081||FATAL|NLogTest.Program|NLog Fatal from Main() |url: |action: 
2020-05-26 09:48:41.9009||INFO|NLogTest.Controllers.WeatherForecastController|ILogger LogInformation from WeatherForecastController. |url: https://localhost/weatherforecast|action: Get
2020-05-26 09:48:41.9162||WARN|NLogTest.Controllers.WeatherForecastController|ILogger LogWarning from WeatherForecastController. |url: https://localhost/weatherforecast|action: Get
2020-05-26 09:48:41.9162||ERROR|NLogTest.Controllers.WeatherForecastController|ILogger LogError from WeatherForecastController. |url: https://localhost/weatherforecast|action: Get
2020-05-26 09:48:41.9219||FATAL|NLogTest.Controllers.WeatherForecastController|ILogger LogCritical from WeatherForecastController. |url: https://localhost/weatherforecast|action: Get

Now can someone tell me why ILogger isn't writing TRACE and DEBUG messages? I have been Googling this for hours, and as far as I can see everything should be set up properly(?).

Thank you!

Answer 1

This problem is related to the default filter in the Microsoft Dependency Injection package. If you use it separately from Asp.net, then you need to configure it something like this:

services.AddLogging(builder => {
    builder.AddFilter(level => level >= LogLevel.Trace);
});

Then all levels will be displayed.

Answer 2

I ran into a similar problem in an existing code base- Trace and Debug statements where not making it into NLog. I found this in the Startup class:

services.AddLogging(builder => builder.AddFilter<NLogLoggerProvider>(null, LogLevel.Information));

If you've run into this problem, and you're sure you've got the correct configuration, check your startup for filters.

Answer 3

As rolf says, if you just debug the asp.net core application by using Visual studio IIS express, you should use appsettings.development.json instead of appsettings.json, since the ASPNETCORE_ENVIRONMENT environment Variables has changed to the Development.

You could find below settings in the launchSettings.json:

  "profiles": {
    "IIS Express": {
      "commandName": "IISExpress",
      "launchBrowser": true,
      "launchUrl": "weatherforecast",
      "environmentVariables": {
        "ASPNETCORE_ENVIRONMENT": "Development"
      }
    },
    "CoreWebAPIIssue": {
      "commandName": "Project",
      "launchBrowser": true,
      "launchUrl": "weatherforecast",
      "applicationUrl": "https://localhost:5001;http://localhost:5000",
      "environmentVariables": {
        "ASPNETCORE_ENVIRONMENT": "Development"
      }
    }
  }

You should modify the appsettings.development.json as below:

{
  "Logging": {
    "LogLevel": {
      "Default": "Trace",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    }
  }
}

The result: