Nlog: ${configsetting} is not correct replaced in Azure App Service with .NET Core 2.2

[oIllenseer]

Hello everyone,

We use nlog to write our logfile to Azure blob storage. Please note that this example was created with dummy values because we don't like to publish our connectionstring.

our configuration file:

<?xml version="1.0" encoding="utf-8" ?>
<!-- XSD manual extracted from package NLog.Schema: https://www.nuget.org/packages/NLog.Schema-->
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true"
      internalLogFile="/home/var/log/console-nlog-internal.log"
      internalLogLevel="Info">

  <extensions>
    <add assembly="NLog.Extensions.AzureStorage"/>
  </extensions>

  <targets>
    <target xsi:type="AzureBlobStorage" name="targetAzure" blobName="WebService\Logging\${date:universalTime=true:format=yyyyMMdd}\${date:universalTime=true:format=HH}.log" container="**${configsetting:name=Storage.ContainerName}**"
            connectionString="**${configsetting:name=Storage.StorageConnectionString}**"    layout="${date:universalTime=True}|${pad:padding=-5:inner=${level:uppercase=true}}|${pad:padding=-30:inner=${logger:shortName=True}}| ${message:exceptionSeparator=\r\n:withException=True}"/>

    <target xsi:type="File" name="target1" fileName="/home/var/log/IoTHubEventProcessor.log"
layout="${date:universalTime=True}|${pad:padding=-5:inner=${level:uppercase=true}}|${pad:padding=-30:inner=${logger:shortName=True}}| ${message:exceptionSeparator=\r\n:withException=True}"
            maxArchiveFiles="20"
            archiveEvery="Day"
            concurrentWrites="false" />

    <target xsi:type="Console" name="target2"
layout="${date:universalTime=True}|${pad:padding=-5:inner=${level:uppercase=true}}|${pad:padding=-30:inner=${logger:shortName=True}}| ${message:exceptionSeparator=\r\n:withException=True}" />
    <target xsi:type="Trace" name="trace" layout="${logger} ${message} ${exception:format=tostring}" />
  </targets>
  <rules>
    <logger name="*" minlevel="Info" writeTo="targetAzure,target1,target2,trace" />
  </rules>
</nlog>

our appsettings.json

{
  "Storage": {
    "StorageConnectionString": "**brdh<wran<wrea**",
    "ContainerName": "**bysdfhash**"
  }
}

the implementation:

var config = new ConfigurationBuilder()
.SetBasePath(AppDomain.CurrentDomain.BaseDirectory)
.AddJsonFile("appsettings.json")
.AddEnvironmentVariables()
.Build();

ConfigSettingLayoutRenderer.DefaultConfiguration = config;

var serviceCollection = new ServiceCollection();
serviceCollection.AddLogging(b =>
{
   b.ClearProviders();
   b.SetMinimumLevel(LogLevel.Trace);
   b.AddNLog(new NLogProviderOptions
   {
      CaptureMessageTemplates = true,
      CaptureMessageProperties = true
   });
})
.BuildServiceProvider();

var builder = new ContainerBuilder();
builder.Populate(serviceCollection);
builder.RegisterModule(new ModuleDefinition());
_eventProcessorContainer = builder.Build();

var serviceProvider = new AutofacServiceProvider(_eventProcessorContainer);

_logger = _eventProcessorContainer.Resolve<ILogger<Program>>();
_logger.LogInformation("Starting application...");
_logger.LogInformation(ConfigSettingLayoutRenderer.DefaultConfiguration.GetValue<string>("Storage.ContainerName"));
_logger.LogInformation(ConfigSettingLayoutRenderer.DefaultConfiguration.GetValue<string>("Storage.StorageConnectionString"));
_logger.LogInformation(ConfigSettingLayoutRenderer.DefaultConfiguration["Storage.ContainerName"]);
_logger.LogInformation(ConfigSettingLayoutRenderer.DefaultConfiguration["Storage.StorageConnectionString"]);

Application settings of the service we added the follow settings:

Storage.ContainerName --> **storedata**
Storage.StorageConnectionString --> **myString**

If we start everything we have this in the logs of nlog:

2019-03-14 08:51:05.0827 Info Auto loading assembly file: D:\local\Temp\jobs\continuous\IoTHubEventProcessor\qopqrzwc.3sj\NLog.Extensions.AzureStorage.dll
2019-03-14 08:51:05.0893 Info Loading assembly file: D:\local\Temp\jobs\continuous\IoTHubEventProcessor\qopqrzwc.3sj\NLog.Extensions.AzureStorage.dll
2019-03-14 08:51:05.1341 Info NLog.Extensions.AzureStorage, Version=1.1.1.0, Culture=neutral, PublicKeyToken=null. File version: 1.1.1.0. Product version: 1.1.1.
2019-03-14 08:51:05.2318 Info Auto loading assembly file: D:\local\Temp\jobs\continuous\IoTHubEventProcessor\qopqrzwc.3sj\NLog.Extensions.AzureStorage.dll succeeded!
2019-03-14 08:51:05.2318 Info Auto loading assembly file: D:\local\Temp\jobs\continuous\IoTHubEventProcessor\qopqrzwc.3sj\NLog.Extensions.Configuration.dll
2019-03-14 08:51:05.2318 Info Loading assembly file: D:\local\Temp\jobs\continuous\IoTHubEventProcessor\qopqrzwc.3sj\NLog.Extensions.Configuration.dll
2019-03-14 08:51:05.2709 Info NLog.Extensions.Configuration, Version=1.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c. File version: 1.3.0.804. Product version: 1.3.0.
2019-03-14 08:51:05.2709 Info Auto loading assembly file: D:\local\Temp\jobs\continuous\IoTHubEventProcessor\qopqrzwc.3sj\NLog.Extensions.Configuration.dll succeeded!
2019-03-14 08:51:05.2780 Info Auto loading assembly file: D:\local\Temp\jobs\continuous\IoTHubEventProcessor\qopqrzwc.3sj\NLog.Extensions.Logging.dll
2019-03-14 08:51:05.2780 Info Loading assembly file: D:\local\Temp\jobs\continuous\IoTHubEventProcessor\qopqrzwc.3sj\NLog.Extensions.Logging.dll
2019-03-14 08:51:05.2780 Info NLog.Extensions.Logging, Version=1.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c. File version: 1.4.0.867. Product version: 1.4.0.
2019-03-14 08:51:05.2780 Info Auto loading assembly file: D:\local\Temp\jobs\continuous\IoTHubEventProcessor\qopqrzwc.3sj\NLog.Extensions.Logging.dll succeeded!
2019-03-14 08:51:05.2949 Info Message Template Auto Format enabled
2019-03-14 08:51:05.2949 Info Loading assembly: NLog.Extensions.AzureStorage
2019-03-14 08:51:05.3844 Info Adding target AzureBlobStorage Target[targetAzure]
2019-03-14 08:51:05.4165 Info Adding target File Target[target1]
2019-03-14 08:51:05.4165 Info Adding target Console Target[target2]
2019-03-14 08:51:05.4550 Info Adding target Trace Target[trace]
2019-03-14 08:51:05.4770 Info Configured from an XML element in D:\local\Temp\jobs\continuous\IoTHubEventProcessor\qopqrzwc.3sj\NLog.config...
2019-03-14 08:51:05.5344 Info Found 63 configuration items
2019-03-14 08:51:05.6385 Error AzureBlobStorageTarget(Name=targetAzure): Failed to create BlobClient with connectionString=**brdh<wran<wrea**. Exception: System.FormatException: Settings must be of the form "name=value".
   at Microsoft.WindowsAzure.Storage.CloudStorageAccount.<>c.<Parse>b__97_0(String err)
   at Microsoft.WindowsAzure.Storage.CloudStorageAccount.ParseStringIntoSettings(String connectionString, Action`1 error)
   at Microsoft.WindowsAzure.Storage.CloudStorageAccount.ParseImpl(String connectionString, CloudStorageAccount& accountInformation, Action`1 error)
   at Microsoft.WindowsAzure.Storage.CloudStorageAccount.Parse(String connectionString)
   at NLog.Extensions.AzureStorage.BlobStorageTarget.InitializeTarget()
2019-03-14 08:51:05.6385 Error AzureBlobStorage Target[targetAzure]: Error initializing target Exception: System.FormatException: Settings must be of the form "name=value".
   at Microsoft.WindowsAzure.Storage.CloudStorageAccount.<>c.<Parse>b__97_0(String err)
   at Microsoft.WindowsAzure.Storage.CloudStorageAccount.ParseStringIntoSettings(String connectionString, Action`1 error)
   at Microsoft.WindowsAzure.Storage.CloudStorageAccount.ParseImpl(String connectionString, CloudStorageAccount& accountInformation, Action`1 error)
   at Microsoft.WindowsAzure.Storage.CloudStorageAccount.Parse(String connectionString)
   at NLog.Extensions.AzureStorage.BlobStorageTarget.InitializeTarget()
   at NLog.Targets.Target.Initialize(LoggingConfiguration configuration)
2019-03-14 08:51:05.6642 Info Configuration initialized.
2019-03-14 08:51:05.6741 Info NLog, Version=4.0.0.0, Culture=neutral, PublicKeyToken=5120e14c03d0593c. File version: 4.5.11.8645. Product version: 4.5.11.

And this are our costume logs:

2019/03/14 08:51:05.704|INFO |Program                       | Starting application...
2019/03/14 08:51:05.830|INFO |Program                       | **storedata**
2019/03/14 08:51:05.830|INFO |Program                       | **myString**
2019/03/14 08:51:05.830|INFO |Program                       | **storedata**
2019/03/14 08:51:05.830|INFO |Program                       | **myString**

• What is the current result?
  Nlog is using the settings from appsettings.log and not the settings that we pass to it with ConfigSettingLayoutRenderer.DefaultConfiguration = config;

• What is the expected result?
  Nlog should use the settings hat we are also able to log, because this are the settings that we configure in Azure

Additional test with DEBUG logging
console-nlog-internal.log

[snakefoot]

Happy to see all my hard work finally is rewarded:

Initial attempt:

• The initial version of ${configsetting} was almost a copy of the existing project https://www.nuget.org/packages/NLog.Appsettings.Standard/
• The initial version loaded the appsettings.json directly without regard for the configuration used by the hosting environment.
• The initial version was promoted as included in NLog.Extension.Logging, but actually one have to use NLog.Extension.Configuration (Very nice trap there)

Second attempt (NLog.Extension.Logging ver. 1.4.0)

• Second attempt recognized that not all applications are only using appsettings.json, and therefore tries to hook into the config of the hosting environment.
• Second attempt moved the code from NLog.Extension.Configuration to NLog.Extension.Logging, because the default dependencies for https://www.nuget.org/packages/Microsoft.Extensions.Logging/2.1.0 (LTS) also include dependency on Microsoft.Extensions.Options (Two packages didn't make sense).
• Second attempt suddenly required one to include NLog.Extension.Logging in <extensions>-xml-section or else it would not load nlog.config.

NLog 4.6 will improve the usability of ${configsetting} so it is automatically loaded/recognized without needing to update <extensions>

[snakefoot]

The solution for you is to get rid of the initial attempt and use the second attempt:

• Remove NLog.Extension.Configuration as nuget-package dependency
• Remove NLog.Extension.Configuration from <extensions>-section in nlog.config
• Update to NLog.Extension.Logging ver. 1.4.0
• Add NLog.Extension.Logging to the <extensions>-section in nlog.config (Not needed when using NLog 4.6)

[snakefoot]

@304NotModified Created https://github.com/NLog/NLog.Extensions.Logging/issues/266 for you to resolve

[304NotModified]

I think I should deprecate NLog.Extensions.Configuration on nuget, isn't?

[304NotModified]

Lol I see now https://github.com/NLog/NLog.Extensions.Logging/issues/266

[oIllenseer]

i'm a little confused about the comments and the label question.
Because i didn't used the package NLog.Extension.Configuration

i did the test today with the follow Packages:

<PackageReference Include="NLog" Version="4.6.0" />
<PackageReference Include="NLog.Extensions.AzureStorage" Version="1.1.1" />
<PackageReference Include="NLog.Extensions.Logging" Version="1.4.0" />

and have the same issues.

[snakefoot]

NLog 4.6 removes the need to include NLog.Extensions.Logging in <extensions> when using ${configsetting}. By removing NLog.Extensions.Configuration then you are able to use hosting environment specific appsettings with ConfigSettingLayoutRenderer.

Your current problem is probably caused by having loaded the NLog config before having loaded appsettings.json

Try and perform an explicit reload of NLog cinfig after having loaded appsettings.json to see if the case:

NLog.LogManager.Configuration = NLog.LogManager.Configuration?.Reload();

See also https://github.com/NLog/NLog.Extensions.Logging/issues/265 for investigating how to make it easier setup NLog with dependency-injection and external config.

[oIllenseer]

Thanks for the answer. The issue is that if an appsettings.json, he is using it but we like to have the settings that are configured in Azure. This values are Provided to ConfigSettingLayoutRenderer but not used. I tried with Log.LogManager.Configuration.Reload(); direct after loading the logger and i can see in the debug log that he is reloading and adding the target:

2019-03-22 12:44:11.6982 Info Adding target BlobStorageTarget(Name=targetAzure)

But i cannot see that log file on the blob storage. The logging of my application is showing the correct connection string in ConfigSettingLayoutRenderer.

nlog.config.txt
console-nlog-internal (3).log

[snakefoot]

To me it looks like the reload fixes the issue with blank connectionString. BlobStorageTarget initializes without errors the second time.

Not that skilled with diagnosing issues with BlobStorageTarget.

[304NotModified]

Has your question being answered?

[304NotModified]

I assume your question has been answered, if not, please let us know!

[snakefoot]

@oIllenseer I have created a wiki-page that describes how to initialize NLog-config:

https://github.com/NLog/NLog/wiki/Reinitialize-NLog-configuration

[snakefoot]

NLog.Web.AspNetCore ver 4.9.3 has been released, and now you can do this:

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

That replaces the old style:

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