Multi thread and async logging is start very late and missing same logs

[iozcelik]

I change a worker service log target to MongoDB from file. However, I observe some log lines are missing. Also, writing logs on collection start about a few seconds later. My 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">
  <extensions>
    <add assembly="NLog.Mongo"/>
  </extensions>

  <targets>
    <target name="mongoTest" xsi:type="AsyncWrapper">
      <target xsi:type="Mongo"
          includeDefaults="false"
          connectionString="mongodb://localhost:27017/Logging"
          collectionName="CustomLogAsyncSecond"
          cappedCollectionSize="2621440000">
        <field name="Logger" layout="${logger}"/>
        <field name="ProcessName" layout="${processname:fullName=true}" />
        <field name="Date" layout="${longdate}" bsonType="DateTime" />
        <field name="ThreadID" layout="${threadid}" bsonType="Int32" />
        <field name="ThreadName" layout="${threadname}" />
        <field name="Level" layout="${level}"/>
        <field name="Message" layout="${message}" />
        <field name="Exception" layout="${exception:format=tostring}" />
      </target>
    </target>
  </targets>

  <rules>
    <logger name="*" minlevel="Info" writeTo="mongoTest"/>
  </rules>
</nlog>

And I use:

Microsoft.Extensions.Configuration;
Microsoft.Extensions.DependencyInjection;
Microsoft.Extensions.Logging;
NLog;
NLog.Extensions.Logging;
System.Threading;

[snakefoot]

Try changing from this:

<target name="mongoTest" xsi:type="AsyncWrapper">

To include overflowAction (Default is Discard):

<target name="mongoTest" xsi:type="AsyncWrapper" overflowAction="Grow">

Maybe missing loglines is because you have configured cappedCollectionSize.

NLog.Mongo/src/NLog.Mongo/MongoTarget.cs

Lines 413 to 422 in ef7c483

	if (!CappedCollectionSize.HasValue || CollectionExists(database, collectionName))
	return database.GetCollection<BsonDocument>(collectionName);
	// create capped
	var options = new CreateCollectionOptions
	{
	Capped = true,
	MaxSize = CappedCollectionSize,
	MaxDocuments = CappedCollectionMaxItems
	};

Looks like #25 also complains about startup delay. Have created #41 for using NLog InternalLogger for performance measurements when connecting.

Maybe you can try this pre-release-nuget-package and report the output from NLog InternalLogger (At Debug-Level):

https://ci.appveyor.com/project/LoreSoft/nlog-mongo/builds/33782375/artifacts

[iozcelik]

I change and try pre-nuget package but it is same.

As you can see from screenshot, the delay is almost 2 minutes. I think miliseconds delays are acceptable but over minutes delays are huge.

[snakefoot]

Can you attach the output from NLog InternalLogger?

[iozcelik]

I attach all file from last run.

logMongoTest.txt

[snakefoot]

You are not using the pre-release build ver. 4.6.0.97 but still using ver. 4.6.0.86 Can you try and perform the test with the pre-release build? (from link above) Btw curious what is going on in your test application, since it is constantly triggering "Hide assemblies for callsite" (unrelated noise to the MongoDb issue)

[iozcelik]

Sorry, l forget change version before last test. I change version and result 2 seconds delay.

All code is here:

public static class NLogTest {
        public static void StartTest() {
            var logger = LogManager.GetCurrentClassLogger();
            try {
                var config = new ConfigurationBuilder()
                   .SetBasePath(System.IO.Directory.GetCurrentDirectory())
                   .AddJsonFile("appsettings.json", optional: true, reloadOnChange: true)
                   .Build();

                logger.Info("Başladı");
                for (int i = 0; i < 100; i++) {
                    new Thread(() => {
                        var servicesProvider = BuildDi(config);
                        using (servicesProvider as IDisposable) {
                            var runner = servicesProvider.GetRequiredService<LogTest>();
                            runner.DoAction("NLog",i);
                        }
                    }).Start();
                }
                Console.WriteLine("Press ANY key to exit");
                Console.ReadKey();

            } catch (Exception ex) {
                Console.WriteLine(ex);

                logger.Error(ex, "Stopped program because of exception");
                throw;
            } finally {
                Console.WriteLine("Logger kapandı");

                LogManager.Shutdown();
            }
        }

        private static IServiceProvider BuildDi(IConfiguration config) {
            return new ServiceCollection()
               .AddTransient<LogTest>() 
               .AddLogging(loggingBuilder => {
                   loggingBuilder.ClearProviders();
                   loggingBuilder.SetMinimumLevel(Microsoft.Extensions.Logging.LogLevel.Trace);
                   loggingBuilder.AddNLog(config);
               })
               .BuildServiceProvider();
        }

    }

public class LogTest {
        private readonly ILogger<LogTest> _logger;

        public LogTest(ILogger<LogTest> logger) {
            _logger = logger;
        }

        public void DoAction(string name,int id) {
            for (int i = 0; i < 100; i++) {
                _logger.LogInformation(id, "Doing hard work! {Action}", name);
            }
        }
    }

[snakefoot]

I change version and result 2 seconds delay.

Looks like the pre-release-build has improved the performance.

Looked at your test-application. And it seems the "Hide assemblies for callsite" comes from each of the 100 threads setting up their own DI-Container with new NLog-LoggingProvider. Where each the NLog-LoggingProvider marks the same Microsoft-extension-logging-dlls to be excluded in callsite-stacktrace-filtering (if callsite should be used).

The same 100 NLog-LoggingProvider performs implicit Flush on thread-exit (when disposing DI-container), thus also causing the frequent logging of "LogFactory Flush with timeout=15 secs"

[snakefoot]

@iozcelik There is now an updated nuget-package, that should match the pre-release:

https://www.nuget.org/packages/NLog.Mongo/

[iozcelik]

Looked at your test-application. And it seems the "Hide assemblies for callsite" comes from each of the 100 threads setting up their own DI-Container with new NLog-LoggingProvider. Where each the NLog-LoggingProvider marks the same Microsoft-extension-logging-dlls to be excluded in callsite-stacktrace-filtering (if callsite should be used).

Thanks I see, however my main aim is testing nlog mongo and I think I will use in my service.