Default .NET Core NLog setup breaks ConfigSettingRenderLayout

[SirBisgaard]

Bug

NLog version: 4.6.8 NLog.Extensions.Logging version: 1.6.1 NLog.Web.AspNetCore version: 4.9.0

Platform: .NET Core 3.2 Current 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>
    <target name="database" xsi:type="Database" dbProvider="Microsoft.Data.SqlClient.SqlConnection, Microsoft.Data.SqlClient"
            connectionString="${configsetting:name=ConnectionStrings.NLOG}">
      <commandText>
        EXEC LogInsert @MachineName, @Service, @Logged, @Identity, @CorrelationId, @Level, @Message, @Logger, @Callsite, @Exception
      </commandText>
      <parameter name="@MachineName" layout="${machinename}" />
      <parameter name="@Logged" layout="${date}" />
      <parameter name="@Service" layout="FTZPlusGlobalApi" />
      <parameter name="@Identity" layout="${aspnet-user-identity}" />
      <parameter name="@CorrelationId" layout="${activityid}" />
      <parameter name="@Level" layout="${level}" /> 
      <parameter name="@Message" layout="${message}" />
      <parameter name="@Logger" layout="${logger}" />
      <parameter name="@Callsite" layout="${callsite}" />
      <parameter name="@Exception" layout="${exception:tostring}" />
    </target>

    <!-- 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>
    <!--Skip non-critical Microsoft logs and so log only own logs-->
    <!--<logger name="Microsoft.*" maxlevel="Info" final="true" />-->
    <!--All logs, including from Microsoft-->
    <!--<logger name="*" minlevel="Trace" writeTo="allfile" />-->
    <logger name="*" minlevel="Trace" writeTo="database" />
    <!-- BlackHole without writeTo -->
    <!--<logger name="*" minlevel="Trace" writeTo="ownFile-web" />-->
  </rules>
</nlog>

• What is the current result? We have followed the guide provided at Getting started with ASP.NET Core 3 As seen in our config we use the ConfigSettingRenderLayout, to get the connection string from our app settings. The problem is that the render does not pick up the connection string from our app settings. And the internal log is prompting the error message from the layout render class.

  InternalLogger.Debug("Missing DefaultConfiguration. Remember to provide IConfiguration when calling AddNLog");

  The problem is only present when I debug the code but not when deploying the project to our IIS servers. I have tried to find the source of the problem. And when I comment out the NLog code in the Program.cs file as shown below. It had no problem finding the connection string in the app settings.

  public static void Main(string[] args)
  {
  //var logger = NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
  try
  {
      //logger.Debug("init 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();
  }
  }

  So I think the issue is that the configure NLog statement in Program.cs does not have a reference to app settings at that moment, but when loading nlog later it does not reload/reapply the layout render with the new configuration. I hope it makes some sense... :-)

• What is the expected result? That the layout render gets the IConfiguration so it can get the connection string.

• Please post full exception details (message, stacktrace, inner exceptions)

  2020-03-10 10:16:16.1974 Info Message Template Auto Format enabled
  2020-03-10 10:16:16.2139 Info Loading assembly: NLog.Web.AspNetCore
  2020-03-10 10:16:16.2829 Info Adding target DatabaseTarget(Name=database)
  2020-03-10 10:16:16.2992 Info Adding target FileTarget(Name=allfile)
  2020-03-10 10:16:16.2992 Info Adding target FileTarget(Name=ownFile-web)
  2020-03-10 10:16:16.3124 Warn Unused target detected. Add a rule for this target to the configuration. TargetName: allfile
  2020-03-10 10:16:16.3124 Warn Unused target detected. Add a rule for this target to the configuration. TargetName: ownFile-web
  2020-03-10 10:16:16.3417 Info Found 80 configuration items
  2020-03-10 10:16:16.4787 Error DatabaseTarget(Name=database): Error when writing to database. Exception: System.InvalidOperationException: The ConnectionString property has not been initialized.
  at Microsoft.Data.SqlClient.SqlConnection.PermissionDemand()
  at Microsoft.Data.SqlClient.SqlConnectionFactory.PermissionDemand(DbConnection outerConnection)
  at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
  at Microsoft.Data.ProviderBase.DbConnectionClosed.TryOpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
  at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)
  at Microsoft.Data.SqlClient.SqlConnection.Open()
  at NLog.Targets.DatabaseTarget.OpenConnection(String connectionString)
  at NLog.Targets.DatabaseTarget.EnsureConnectionOpen(String connectionString)
  at NLog.Targets.DatabaseTarget.WriteEventToDatabase(LogEventInfo logEvent, String connectionString)
  at NLog.Targets.DatabaseTarget.Write(LogEventInfo logEvent)

• Are there any work arrounds? yes/no Yes but it breaks the best practice guide provided by the framework.

• Is there a version in which it did worked? No.

• Can you help us by writing an unit test? No.

[SirBisgaard]

Jesus, I hope my issue will be found with this Id #404...

[snakefoot]

Sounds like a duplicate of #265 . NLog cannot read ${configsetting}-options before having loaded appsettings.json.

Chicken and the egg problem. You want the logging-framework up and running early, but suddenly it depends on having loaded appsettings.json.

I'm hoping that LogFactory.Setup in NLog 4.7 will make it easier to hook NLog together with Extension Logging (and friends). Thus removing NLogBuilder.ConfigureNLog("nlog.config")

[SirBisgaard]

It is like that issue #265. But should the documentation not be changed to match this problem? For example on the layout render it should state that this problem will occur when using web APIs.

[snakefoot]

@SirBisgaard You are completely right. Think the problem is that I have never used NLog.Extensions.Logging for anything. So I'm not the best person for writing documentation for this. I have tried to explain how it works here:

https://github.com/NLog/NLog/wiki/ConfigSetting-Layout-Renderer

But I have also tried to implement logic so it will automatically register itself using AddNLog and UseNLog (To make it more userfriendly, as you have witnessed when not using NLogBuilder). Ofcourse this is not possible using NLogBuilder.ConfigureNLog (Happens before HostBuilder). Which is the reason I will try to get rid of it and instead replace it with extension-methods on LogFactory.Setup in NLog 4.7.

Again NLog is a community project that is developed in peoples spare time. The more contribution the project gets the faster the development will become.

[snakefoot]

With NLog.Web.AspNetCore ver. 4.9.3 then you can replace this:

var logger = NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();

With:

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

Allowing logging to work before having started hosting-environment.