NLog writes to all targets from my machine but fails writing to Database target on application server

0

Quick summary before getting into the nitty gritty

(NLog version 4.7.2) ASP.NET Core 2.2 web application correctly logs to file & database targets from local machine. As soon as it's deployed to staging application server, file logging continues but database logging doesn't work and gives no errors in internal log. Created a console application with NLog running on .NET Core 2.2 and it correctly logs to file & database from local machine and the same server that the web application is being deployed to.


Problem & Details

I recently went through and added a logging solution to an application we're building and it's been a relatively painless process. Setting up file / database targets was a breeze and I was able to write logs from the application to both a dev & staging database with no problems.

The application is a .NET CORE 2.2 web application and it uses NLog 4.7.2 - setup below.

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"
  throwConfigExceptions="true"
  internalLogLevel="Debug"
  internalLogFile="c:\temp\internal-nlog.txt">

<!-- enable asp.net core layout renderers -->
<extensions>
  <add assembly="NLog.Extensions.Logging"/>
  <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}" />

<!-- write to the void aka just remove -->
<target xsi:type="Null" name="blackhole" />

<!--<target name="databaseLogger" xsi:type="Database"
            dbProvider="sqlserver"
            dbHost="${configsetting:name=AppSettings.NlogConnection.DbHost}"
            dbDatabase="${configsetting:name=AppSettings.NlogConnection.Database}"
            dbUserName="${configsetting:name=AppSettings.NlogConnection.User}"
            dbPassword="${configsetting:name=AppSettings.NlogConnection.Password}">-->
<target name="databaseLogger" xsi:type="Database"
      dbProvider="sqlserver"
      dbHost="${configsetting:AppSettings.NlogConnection.DbHost}"
      dbDatabase="${configsetting:AppSettings.NlogConnection.Database}"
      dbUserName="${configsetting:AppSettings.NlogConnection.User}"
      dbPassword="${configsetting:AppSettings.NlogConnection.Password}" >

  <!--<target name="databaseLogger" xsi:type="Database" connectionString="${configsetting:AppSettings.NlogConnection.AppLogsConnectionString}">-->

  <commandText>
    insert into dbo.Log (
    CorrelationId, Application, ObjectID, Logged, Level, Message,
    Logger, CallSite, Exception
    ) values (
    @CorrelationId, @Application, @ObjectID, @Logged, @Level, @Message,
    @Logger, @Callsite, @Exception
    );
  </commandText>
  <parameter name="@correlationId" layout="${aspnet-traceidentifier}" />
  <parameter name="@application" layout="${configsetting:AppSettings.NlogConnection.AppName}" />
  <parameter name="@ObjectID" layout="${aspnet-user-identity}" />
  <!--https://github.com/NLog/NLog/issues/2772-->
  <parameter name="@logged" layout="${date}" />
  <parameter name="@level" layout="${level}" />
  <parameter name="@message" layout="${message}" />
  <parameter name="@logger" layout="${logger}" />
  <parameter name="@callSite" layout="${callsite:filename=false}" />
  <parameter name="@exception" layout="${exception:toString}" />
</target>

</targets>

<!-- rules to map from logger name to target -->
<rules>
<!--Skip non-critical Microsoft logs and so log only own logs-->
<!-- Microsoft logger will automatically catch and log all automated warn, error & fatal messages (such as uncaught exceptions) -->
<logger name="Microsoft.*" levels="Warn, Error, Fatal" writeTo="databaseLogger"></logger>
<logger name="Microsoft.*" minLevel="Trace" final="true" />

<!-- BlackHole without writeTo -->
<!--<logger name="Microsoft.*" minLevel="Trace" writeTo="" final="true" />-->
<!-- BlackHole with writeTo -->
<!--<logger name="Microsoft.*" minLevel="Trace" writeTo="blackhole" final="true" />-->
<!-- BlackHole without writeTo -->

<!--All logs, including from Microsoft unless suppressed (which I do, above)-->
<logger name="*" minlevel="Trace" writeTo="allfile" />
<logger name="*" minlevel="${configsetting:AppSettings.NlogConnection.LogLevel" writeTo="databaseLogger" />
<logger name="*" minlevel="Trace" writeTo="ownFile-web" />
  </rules>
</nlog>

relevant snippet from appsettings.json

"NlogConnection": {
      "LogLevel": "Trace",
      "AppName": "NetCoreApp",
      "DbProvider": "sqlserver",
      "DbHost": "dev-sql01",
      "Database": "AppLogs",
      "User": "NLog",
      "Password": "***********"
    }

Program.cs

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

namespace Website
{
    public class Program
    {
        public static void Main(string[] args)
        {
            // NLog: setup the logger first to catch all errors
            var logger = NLogBuilder.ConfigureNLog("nlog.config").GetCurrentClassLogger();
            try
            {
                // These messages are found in the nlog-all-{today} text file
                logger.Debug("init main");
                CreateWebHostBuilder(args).Build().Run();
            }
            catch (Exception ex)
            {
                //NLog: catch setup errors
                logger.Error(ex, "Stopped program because of exception");
                throw;
            }
            finally
            {
                // Ensure to flush and stop internal timers/threads before application-exit
                NLog.LogManager.Shutdown();
            }
        }

        public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
            WebHost.CreateDefaultBuilder(args)
                .UseStartup<Startup>()
                .ConfigureLogging(logging =>
                {
                    logging.ClearProviders();
                    // The Logging configuration specified in appsettings.json overrides any call to SetMinimumLevel.
                    logging.SetMinimumLevel(LogLevel.Trace);
                })
                .UseNLog();  // NLog: setup NLog for Dependency injection
    }
}

My local dev machine has IIS 10.0 Express installed. This setup works exactly as it should. I get file logging to my temp directory, database rows are created from my logger statements and all is good. I can swap to another connection string for the staging SQL server and I get logs written there as well.

As soon as I publish this to one of our Windows servers (Dev or Staging - they both are configured the same from what I can see) I get file logging but no database logging. The files created show no errors either and I am able to ping the SQL servers from the application servers.

The servers are running Windows Server 2012 R2 and IIS 8.5.

The internal log will (not always) display the following exception message when attempting to run the web application - but I never get anything like this with the console application.

2020-08-21 12:33:17.7505 Error DatabaseTarget(Name=databaseLogger): Error when writing to database. Exception: System.Data.SqlClient.SqlException (0x80131904): A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server) ---> System.ComponentModel.Win32Exception (2): The system cannot find the file specified
   at System.Data.SqlClient.SqlInternalConnectionTds..ctor(DbConnectionPoolIdentity identity, SqlConnectionString connectionOptions, SqlCredential credential, Object providerInfo, String newPassword, SecureString newSecurePassword, Boolean redirectedUserInstance, SqlConnectionString userConnectionOptions, SessionData reconnectSessionData, Boolean applyTransientFaultHandling, String accessToken)
   at System.Data.SqlClient.SqlConnectionFactory.CreateConnection(DbConnectionOptions options, DbConnectionPoolKey poolKey, Object poolGroupProviderInfo, DbConnectionPool pool, DbConnection owningConnection, DbConnectionOptions userOptions)
   at System.Data.ProviderBase.DbConnectionFactory.CreatePooledConnection(DbConnectionPool pool, DbConnection owningObject, DbConnectionOptions options, DbConnectionPoolKey poolKey, DbConnectionOptions userOptions)
   at System.Data.ProviderBase.DbConnectionPool.CreateObject(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
   at System.Data.ProviderBase.DbConnectionPool.UserCreateRequest(DbConnection owningObject, DbConnectionOptions userOptions, DbConnectionInternal oldConnection)
   at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, UInt32 waitForMultipleObjectsTimeout, Boolean allowCreate, Boolean onlyOneCheckConnection, DbConnectionOptions userOptions, DbConnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionPool.TryGetConnection(DbConnection owningObject, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)
   at System.Data.SqlClient.SqlConnection.Open()
   at NLog.Targets.DatabaseTarget.OpenConnection(String connectionString, LogEventInfo logEventInfo)
   at NLog.Targets.DatabaseTarget.EnsureConnectionOpen(String connectionString, LogEventInfo logEventInfo)
   at NLog.Targets.DatabaseTarget.WriteLogEventToDatabase(LogEventInfo logEvent, String connectionString)
ClientConnectionId:00000000-0000-0000-0000-000000000000
Error Number:2,State:0,Class:20

What I tried

To narrow things down I followed the instructions here to create a simple console application that used NLog to write to files. It worked on my local dev machine, so I published it as an executable and put it on the servers and sure enough I get file logging on the server.

I then added a new table to the database, edited the nlog.config (shown below) to add a database target and lo and behold it worked as expected on my local machine. Plugging in both the dev & staging SQL server information gave me both file & database logging.

<?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="NLog NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
      autoReload="true"
      internalLogFile="c:\temp\console-example-internal.log"
      internalLogLevel="Info" >

  <!-- the targets to write to -->
  <targets>
    <!-- write logs to file -->
    <target xsi:type="File" name="target1" fileName="c:\temp\console-example.log"
            layout="${date}|${level:uppercase=true}|${message} ${exception}|${logger}|${all-event-properties}" />
    <target xsi:type="Console" name="target2"
            layout="${date}|${level:uppercase=true}|${message} ${exception}|${logger}|${all-event-properties}" />

    <target name="databaseLogger" xsi:type="Database"
            dbProvider="sqlserver"
            dbHost="dev-sql01"
            dbDatabase="AppLogs"
            dbUserName="NLog"
            dbPassword="********************">

      <commandText>
        insert into dbo.ConsoleLog (
        Logged, Level, Message, Logger, CallSite, Exception
        ) values (
        @Logged, @Level, @Message, @Logger, @Callsite, @Exception
        );
      </commandText>
      <parameter name="@logged" layout="${date}" />
      <parameter name="@level" layout="${level}" />
      <parameter name="@message" layout="${message}" />
      <parameter name="@logger" layout="${logger}" />
      <parameter name="@callSite" layout="${callsite:filename=false}" />
      <parameter name="@exception" layout="${exception:toString}" />
    </target>
  </targets>

  <!-- rules to map from logger name to target -->
  <rules>
    <logger name="*" minlevel="Trace" writeTo="target1,target2, databaseLogger" />
  </rules>
</nlog>

I then published the application again with the new target (I know I could have just updated the nlog.config on the server but I wanted to be thorough) and with the console application I get file logging AND database logging working correctly.


Closing thoughts and my question

At this point I'm not really sure what area to investigate. It seems that the odd component out here is IIS on the server but at this rate I'm not sure if there's just some incompatibility with the versions, something configured in a weird way with the server, or something related to the web application code that could be causing the problem.

Does anything obvious stand out as a potential culprit for what could be causing the problem?

c#
asp.net-core
iis
nlog
asked on Stack Overflow Aug 21, 2020 by Mkalafut • edited Aug 21, 2020 by Julian

0 Answers

Nobody has answered this question yet.


User contributions licensed under CC BY-SA 3.0