SignalR Backplane not working with NLog configuration (Clients cannot reconnect)

Question

We have created a server with SQL backplane. Lately, we found this issue which caused the high number of thread usage by w3wp.exe. After going through the entire code base we were able to narrow down that the cause is related with NLog.

We have configured NLog by following configurations in the web config file.

<configuration>
  <configSections>
    <section name="nlog" type="NLog.Config.ConfigSectionHandler, NLog" />
  </configSections>
  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.nlog-project.org/schemas/NLog.xsd NLog.xsd">
    <targets async="true">

      <target name="file" xsi:type="File" fileName="${basedir}/Logs/${shortdate}_printcloud.log" archiveFileName="${basedir}/Logs/ArchiveAuto/{#}_printcloud.log" archiveDateFormat="yyyy-MM-dd" archiveAboveSize="50000000" archiveEvery="Day" archiveNumbering="DateAndSequence" maxArchiveFiles="14" archiveOldFileOnStartup="false" createDirs="true" layout="${longdate} ${uppercase:${level}}  ${logger} ${message} (${callsite:includSourcePath=true}) ${exception:format=tostring}" />

    </targets>
    <rules>
     <logger name="PrintCloud.*" minlevel="Trace" maxlevel="Error" writeTo="file" />-->

    </rules>
  </nlog>
<configuration>

Inside the hub we have used the logger like below.

public class ConnectorHub : Hub
{
    private static NLog.Logger logger = NLog.LogManager.GetCurrentClassLogger();

    public void Connect(string message)
    {
        logger.Debug("Connection Recieved");
        (new SignalRHubHelper()).SendConnectRecieved(Context.ConnectionId);
    }
}

When we run the backplane with these configurations enabled we are facing the issue of high number of thread usage when clients try to reconnect. But if we comment out the NLog configuration code from the web config file the backplane works perfectly fine. Have anyone experienced a similar behaviour to this when using backplane? What might be the cause for this behaviour?

SignalR versoin - 2.2.2 NLog version - 4.4.9

EDIT 1

The problem seems to be not happening when we disable the signalr trace logging from the webconfig. We have used NLog.NLogTraceListener to log signalr traces.

  <system.diagnostics>
    <sources>
      <source name="SignalR.SqlMessageBus">
        <listeners>
          <add name="traces" />
        </listeners>
      </source>
      <source name="SignalR.ServiceBusMessageBus">
        <listeners>
          <add name="traces" />
        </listeners>
      </source>
      <source name="SignalR.RedisMessageBus">
        <listeners>
          <add name="traces" />
        </listeners>
      </source>
      <source name="SignalR.ScaleoutMessageBus">
        <listeners>
          <add name="traces" />
        </listeners>
      </source>
      <source name="SignalR.Transports.WebSocketTransport">
        <listeners>
          <add name="traces" />
        </listeners>
      </source>
      <source name="SignalR.Transports.ServerSentEventsTransport">
        <listeners>
          <add name="traces" />
        </listeners>
      </source>
      <source name="SignalR.Transports.ForeverFrameTransport">
        <listeners>
          <add name="traces" />
        </listeners>
      </source>
      <source name="SignalR.Transports.LongPollingTransport">
        <listeners>
          <add name="traces" />
        </listeners>
      </source>
      <source name="SignalR.Transports.TransportHeartBeat">
        <listeners>
          <add name="traces" />
        </listeners>
      </source>
      <source name="SignalR.ReflectedHubDescriptorProvider">
        <listeners>
          <add name="traces" />
        </listeners>
      </source>
    </sources>
     <!--Sets the trace verbosity level--> 
    <switches>
      <add name="SignalRSwitch" value="Verbose" />
    </switches>
    <sharedListeners>

     <add name="traces" type="NLog.NLogTraceListener, NLog" />
    </sharedListeners>
    <trace autoflush="true" />
  </system.diagnostics>

Rather than using NLog.NLogTraceListener and using System.Diagnostics.TextWriterTraceListener instead also seems to not giving any problem.

Could you test without archiving? Also, are you writing a lot of events? (I see trace level is enabled) — Julian
Yes, I tried removing archiving but the same result is given. In a normal scenario, we have 30+ clients. — Janitha Tennakoon
Tried without async as well. The only thing that seems to work is that changing the rule where logger name = * rather than PrintCloud.* — Janitha Tennakoon
that's strange. The code for filtering those is here (and don't uses threads): github.com/NLog/NLog/blob/…. — Julian

Rolf Kristensen Rolf Kristensen · Accepted Answer · 2017-05-27T22:37:29

Think the problem is this:

autoflush=true

This causes the NLogTraceListener to go beserk and perform flush for every trace-event. By using thread-pool threads to flush all registered NLog-targets.

If you need the autoflush=true, then consider disabling the threadpool flush by adding disableFlush attribute to the listener:

<add name="traces" type="NLog.NLogTraceListener, NLog" disableFlush="true" />

Curious why the NLog Wiki recommends enabling autoflush=true, without adding this important attribute:

https://github.com/NLog/NLog/wiki/NLog-Trace-Listener-for-System-Diagnostics-Trace

Update NLog 4.5 now uses disableFlush=true as default. See also https://github.com/NLog/NLog/pull/2407

SignalR Backplane not working with NLog configuration (Clients cannot reconnect)

1 Answers