Nlog: Network Target Missing Logs/Behaving Asynchronously without Async Wrapper

[amikapoor]

NLog version: 4.6.8

Platform: .NET Core 2

Current NLog config (xml or C#, if relevant)

<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">

  <variable name="basedir" value="${basedir}" />
  <variable name="processname" value="${processname}" />
  <variable name="timestamp" value="${date:universalTime=false:format=MM/dd/yyyy HH\:mm\:ss.fff:culture=en-US}" />
  <variable name="logglyTimestamp" value="${date:universalTime=false:format=yyyy-MM-ddTHH\:mm\:ss.fffffffzzz:culture=en-US}" />
  <variable name="starting" value ="================================================================================${newline}= Starting${newline}================================================================================${newline}" />

  <targets>

    <target
      name="defaultFile"
      xsi:type="File"
      encoding="UTF-8"
      layout="${timestamp} | ${threadid} | ${level:uppercase=true} | ${message} | ${exception:maxInnerExceptionLevel=99:format=tostring} | ${all-event-properties}"
      header="${starting}"
      concurrentWrites="true"
      keepFileOpen="true"
      archiveAboveSize="5000000"
      openFileCacheTimeout="30"
      archiveNumbering="Rolling"
      maxArchiveFiles="10"
      cleanupFileName="false"
      forceManaged="true"
      fileName="${var:basedir}/Logs/${processname}.log"
      archiveFileName="${var:basedir}/Logs/Archive/${processname}.{#}.log" />

    <target
      xsi:type="Network"
      address="http..."
      name="primaryNetwork"
      newLine="true">

      <layout xsi:type="JsonLayout" includeAllProperties="true">
        <attribute name="message" layout="${message}" />
        <attribute name="timestamp" layout="${var:logglyTimestamp}" />
        <attribute name="exception" layout="${exception:maxInnerExceptionLevel=99:format=tostring}" />
        <attribute name="loggerName" layout="${logger}" />
      </layout>

    </target>

  </targets>

  <rules>

    <logger name="Flow" minlevel="Info" writeTo="defaultFile,primaryNetwork" />

  </rules>

</nlog>

```class Program
{
static void Main(string[] args)
{
LogManager.ThrowConfigExceptions = true;
LogManager.ThrowExceptions = true;

        var currentDirectory = Directory.GetCurrentDirectory();
        var pathToConfigFile = Path.Combine(currentDirectory, "NLog.config");
        var config = new XmlLoggingConfiguration(pathToConfigFile);
        LogManager.Configuration = config;

        LogManager.Configuration.Variables["basedir"] = currentDirectory;

        for(int i = 0; i < 10; i++)
        {
            LogManager.GetLogger("Flow").Info(i.ToString());
            //LogManager.Flush();
        }

        //Console.ReadLine();
    }
}

```

• What is the current result?
  When using a network target without an async wrapper, log data may not reliably be sent and exceptions may not be caught leading to app crashes. It seems like logging to a network target is being done asynchronously even without the wrapper. Executing the above code, no log data actually makes it through. If I call Flush(), everything comes through without a problem. If I only call Readline() without Flush() and wait a few seconds before allowing the function to end, everything comes through again.
  Another consequence of how it currently works is that if there is an exception on this background thread that is doing the network logging, it can not be caught and handled by the calling application.

• What is the expected result?
  I would expect logging to network target to happen synchronously when the async wrapper is not there.

• Did you checked the Internal log?
  Yes

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

• Are there any workarounds? yes
  Flush the logs after each log statement

• Is there a version in which it did work?
  Don't think so

• Can you help us by writing an unit test?
  I will try

[welcome[bot]]

Hi! Thanks for opening your first issue here! Please make sure to follow the issue template - so we could help you better!

[snakefoot]

Yes that is the nature of the Network Target it performs all network-requests in async-mode by default. Probably because network is async by default, as there can be a delay from send-request-start to send-request-complete (That should trigger sending the next in queue).

You can ensure that all LogEvents are sent before application exit by calling this method:

NLog.LogManager.Shutdown(); // Will also flush

Like most logging systems then NLog is mostly fire-and-forget. By default it doesn't provide much feedback to the calling application.

Do you have exception-stacktraces from those "exceptions may not be caught leading to app crashes" ? Since the focus of all NLog targets is to handle errors gracefully.

If you are very interested in being notified about network-requests that failed, then you can setup a FallbackGroup-TargetWapper with the Network-target and fallback to the MethodCall-Target that can call a specified method in your application:

[amikapoor]

Thank you for the response.

My use case here is Azure Functions, so Shutdown(); may not always be called just because of the nature of Azure Functions. An instance can just "disappear" at any moment, which is also why I don't have any exception stack traces.

I think if I explain my use case more specifically it would be helpful. This is what my function looks like more or less:

async Task Function(
    [QueueTrigger(inputQueue)]
    CloudQueueMessage inputMessage)
{
    // do some stuff/logging

    await outputQueue.AddMessage(outputMessage);
}

Basically, I just want to do some stuff, do some logging, then add a message to another queue to kick off another function to run.

The issue I'm having is that occasionally, I see some duplicate messages being processed by the 2nd function. How does this happen? Because the function goes through, does some stuff/logging, and adds to the output queue as the last line. Then the 2nd function starts. Meanwhile, the fire and forget nature of Network Targets are somehow not allowing the first function to exit successfully and mark the incomingMessage as processed. So it subsequently tries to process the same message again leading to the duplicate.

The "failed" function times out after 10 minutes so it makes me think there is some network timeout that is happening and not being handled.

Is logging to a File type also fire and forget without the async wrapper? Or can I expect all logging related threads to be done after calling a Log?

[snakefoot]

No File- and Console-logging are not async in NLog (unless using the async-wrapper).

Not an expert on azure-functions, but some people just write to the console (ex in json), that is automatically captured by azure-function. Then one can setup forwarding of the captured console-output to the wanted destination in the azure-function-config.

[304NotModified]

An instance can just "disappear" at any moment, which is also why I don't have any exception stack trace

there is no event so you could do a flush?

[snakefoot]

Alternative rewrite:

async Task Function(
    [QueueTrigger(inputQueue)]
    CloudQueueMessage inputMessage)
{
    // do some stuff/logging

    await outputQueue.AddMessage(outputMessage);
    NLog.LogManager.Flush(); // Will be fast if nothing to flush
}

How do you load the NLog-config? Have seen Azure-functions can "reuse" static loaded variables. So if having static variable with NLog-Logger then it will be reused on all Azure-function-instances running concurrently on the same box.

[amikapoor]

An instance can just "disappear" at any moment, which is also why I don't have any exception stack trace

there is no event so you could do a flush?

There is, but it is not guaranteed to hit that event.

[amikapoor]

Alternative rewrite:

async Task Function(
    [QueueTrigger(inputQueue)]
    CloudQueueMessage inputMessage)
{
    // do some stuff/logging

    await outputQueue.AddMessage(outputMessage);
    NLog.LogManager.Flush();
}

Thank you for that. Only thing I would need to do differently is switch the last 2 lines and flush before adding to the queue because if the flush throws an exception after I've already added to the queue, then function 1 will retry and add another message to function 2 even though that already happened once.

I am loading the config pretty much the same way as above. That's interesting but I do not see that behavior in my case because I log out some machine/host specific stuff.

[snakefoot]

if the flush throws an exception after I've already added to the queue, then function 1 will retry

NLog.LogManager.Flush(); cannot throw unless you are running with LogManager.ThrowExceptions = true (Which is NOT recommended, since only used for unit-testing)

[304NotModified]

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