Does LogManager.Flush() synchronously write all the logs on latest NLog of Netfx40?

[Guohao Tan]

We are using NLog.dll (Version 2.0.0.0, Modified date 12/3/2012, NLog for .Net Framework 3.5), and we encountered the issue that when we call LogManager.Flush(), we expect all pending logs to be written to the log file immediately. While actually the logs seems to be asynchronously written.

This issue is very similar with this topic on stack overflow:  http://stackoverflow.com/questions/10492720/should-nlog-flush-all-queued-messages-in-the-asynctargetwrapper-when-flush-is

Now we want to upgrade latest NLog of Netfx40 to fix this issue, and we have only one FileTarget configured in the configuration file. So does LogManager.Flush() synchronously write all the logs on latest NLog of Netfx40?

Thanks in advance for any help.

[Kim Christensen]

It will still be written asynchronously but it had been changed to LogManager.Flush only will return when all pending logs have been flushed

[谈国颢]

Thanks Kim, we will update to the latest version of NLog(2.0.1) and try again.

2013/8/19 Kim Christensen <kimwo...@gmail.com>

It will still be written asynchronously but it had been changed to LogManager.Flush only will return when all pending logs have been flushed

--
You received this message because you are subscribed to a topic in the Google Groups "NLog-Users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/nlog-users/-V4b0z4QQTc/unsubscribe.
To unsubscribe from this group and all its topics, send an email to nlog-users+...@googlegroups.com.
To post to this group, send email to nlog-...@googlegroups.com.
Visit this group at http://groups.google.com/group/nlog-users.
For more options, visit https://groups.google.com/groups/opt_out.

[Eyal Herlin]

Hi Guohao Tan,

Did you manage to solve this?

Upgrading to the latest version (2.01.2) didn't help me.

Thanks,

Eyal

[Kim Christensen]

Could you provide a sample project reproducing the issue?

[Guohao Tan]

Hi, Kim
Finally I found the repro step of this issue...

Below is our code using NLog. Note logEventInfo.TimeStamp=DateTime.Now, and RaiseLogEvent(logEventInfo) will call logger.Log(logEventInfo) and simply write to a FileTarget

        public void Log(CCLogEventInfoData data)
        {
            Task.Factory.StartNew(delegate()
            {
                if (data != null)
                {
                    LogEventInfo logEventInfo = CreateLogEventInfo(data);
                    RaiseLogEvent(logEventInfo);
                }
            });
        }

Then when the system running with heavy logging traffic, CHANGE THE SYSTEM DATE.

Since the fileTarget is configured as Daily archive, then the following code of FileTarget.cs will be reached

        private bool ShouldAutoArchive(string fileName, LogEventInfo ev, int upcomingWriteSize)
        {
            ...code above is ommited...
                string ts = lastWriteTime.ToString(formatString, CultureInfo.InvariantCulture);
                string ts2 = ev.TimeStamp.ToLocalTime().ToString(formatString, CultureInfo.InvariantCulture);

                if (ts != ts2)
                {
                    return true;
                }
            }

            return false;
        }.

Then the coming calls seems will generate many 1KB log files

private void DoAutoArchive(string fileName, LogEventInfo ev)
        {
            var fi = new FileInfo(fileName);
            if (!fi.Exists)
            {
                return;
            }

            // Console.WriteLine("DoAutoArchive({0})", fileName);
            string fileNamePattern;

            if (this.ArchiveFileName == null)
            {
                string ext = Path.GetExtension(fileName);
                fileNamePattern = Path.ChangeExtension(fi.FullName, ".{#}" + ext);
            }
            else
            {
                //The archive file name is given. There are two possibiliy
                //(1) User supplied the Filename with pattern
                //(2) User supplied the normal filename
                fileNamePattern = this.ArchiveFileName.Render(ev);

            }
           
            if (!IsContainValidNumberPatternForReplacement(fileNamePattern))
            {
                dynamicArchiveFileHandler.AddToArchive(fileNamePattern, fi.FullName,CreateDirs);
            }
            else
            {
                  InternalLogger.Error("Current above size is : {0}", this.ArchiveAboveSize);
                  switch (this.ArchiveNumbering)
                  {
                       case ArchiveNumberingMode.Rolling:
                           this.RecursiveRollingRename(fi.FullName, fileNamePattern, 0);
                           break;

                       case ArchiveNumberingMode.Sequence:
                           this.SequentialArchive(fi.FullName, fileNamePattern);
                           break;
                  }
            }
        }

And the sample output of InternalLogger.Error("Current above size is : {0}", this.ArchiveAboveSize);


2014-01-23 21:52:20.0778 Error Current above size is : 50000000
2014-01-23 21:52:50.1395 Error Current above size is : 50000000
2014-01-23 21:52:50.1555 Error Current above size is : 50000000
2014-01-23 21:52:50.1735 Error Current above size is : 50000000
2014-01-23 21:52:50.1875 Error Current above size is : 50000000
2014-01-23 21:52:50.4725 Error Current above size is : 50000000
2014-01-23 21:52:50.4875 Error Current above size is : 50000000
2014-01-23 21:52:50.5045 Error Current above size is : 50000000
2014-01-24 10:52:50.7065 Error Current above size is : 50000000
2014-01-23 21:52:51.8886 Error Current above size is : 50000000
2014-01-23 21:52:51.9026 Error Current above size is : 50000000
2014-01-23 21:52:51.9166 Error Current above size is : 50000000
2014-01-23 21:52:51.9316 Error Current above size is : 50000000
2014-01-24 10:52:51.9466 Error Current above size is : 50000000
2014-01-24 10:52:51.9466 Error Current above size is : 50000000
2014-01-23 21:52:51.9736 Error Current above size is : 50000000
2014-01-23 21:52:51.9876 Error Current above size is : 50000000
2014-01-24 10:52:52.0026 Error Current above size is : 50000000
2014-01-23 21:52:52.0156 Error Current above size is : 50000000
2014-01-23 21:52:52.0276 Error Current above size is : 50000000
2014-01-23 21:52:52.0406 Error Current above size is : 50000000
2014-01-24 10:52:52.0566 Error Current above size is : 50000000
2014-01-23 21:52:52.0716 Error Current above size is : 50000000
2014-01-23 21:52:52.0886 Error Current above size is : 50000000
2014-01-24 10:52:52.1026 Error Current above size is : 50000000
2014-01-24 10:52:52.1026 Error Current above size is : 50000000
2014-01-23 21:52:52.1276 Error Current above size is : 50000000
2014-01-23 21:52:52.1426 Error Current above size is : 50000000
2014-01-23 21:52:52.1536 Error Current above size is : 50000000
2014-01-24 10:52:52.1706 Error Current above size is : 50000000
2014-01-23 21:52:52.1816 Error Current above size is : 50000000
2014-01-23 21:52:52.1966 Error Current above size is : 50000000
2014-01-23 21:52:52.1966 Error Current above size is : 50000000
2014-01-24 10:52:52.2226 Error Current above size is : 50000000
2014-01-23 21:52:52.2386 Error Current above size is : 50000000
2014-01-23 21:52:52.2516 Error Current above size is : 50000000
2014-01-23 21:52:52.2686 Error Current above size is : 50000000
2014-01-24 10:52:52.2856 Error Current above size is : 50000000
2014-01-23 21:52:52.2966 Error Current above size is : 50000000
2014-01-23 21:52:52.3146 Error Current above size is : 50000000
2014-01-23 21:52:52.3266 Error Current above size is : 50000000
2014-01-24 10:52:52.3376 Error Current above size is : 50000000
2014-01-23 21:52:52.3526 Error Current above size is : 50000000
2014-01-23 21:52:52.3696 Error Current above size is : 50000000
2014-01-23 21:52:52.3696 Error Current above size is : 50000000
2014-01-24 10:52:52.3996 Error Current above size is : 50000000
2014-01-23 21:52:52.4146 Error Current above size is : 50000000
2014-01-23 21:52:52.4146 Error Current above size is : 50000000
2014-01-23 21:52:52.4386 Error Current above size is : 50000000
2014-01-24 10:52:52.4496 Error Current above size is : 50000000
2014-01-23 21:52:52.4616 Error Current above size is : 50000000
2014-01-23 21:52:52.4616 Error Current above size is : 50000000
2014-01-23 21:52:52.4836 Error Current above size is : 50000000
2014-01-24 10:52:52.4926 Error Current above size is : 50000000
2014-01-24 10:52:52.4926 Error Current above size is : 50000000
2014-01-23 21:52:52.5106 Error Current above size is : 50000000
2014-01-23 21:52:52.5106 Error Current above size is : 50000000在此输入代码...

Note the date changes between 01/23 and 01/24.

Our NLog config

  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" autoReload="true" internalLogFile="${basedir}\NLog_Internal.log" internalLogLevel="Error" throwExceptions="true">
    <variable name="ccLogLayout" value="${event-context:item=LogTime}§${event-context:item=Severity}§${event-context:item=FileName}§${event-context:item=LineNumber}§${event-context:item=FunctionName}§${event-context:item=RaisedErrorNamespace}§${event-context:item=PatientGuid}§${event-context:item=ImageGuid}§${event-context:item=UserName}§${event-context:item=UserDefinedKey}§${event-context:item=ErrorNumber}§${event-context:item=Message}§${event-context:item=ExceptionName}§${event-context:item=ExceptionString}§${event-context:item=InnerException}§${event-context:item=MachineName}§${event-context:item=StackTrace}§${event-context:item=ThreadName}§${event-context:item=ThreadId}§${event-context:item=ProcessId}§${event-context:item=ProcessName}§${event-context:item=Number}§${event-context:item=MessageSequence}§${event-context:item=AssemblyName}§${event-context:item=RequestSequenceNumber}§${event-context:item=EventSequenceNumber}§${event-context:item=EventSourceInstance}§${event-context:item=EventSourceName}§${event-context:item=MessageId}" />
    <targets>
      <!-- target for writing to log file that rolls over every day or every 50 MB -->
      <target name="fileTarget" fileName="TraceLog_${shortdate}.log" xsi:type="File" layout="${ccLogLayout}" maxArchiveFiles="100" archiveEvery="Day" archiveAboveSize="50000000" keepFileOpen="true" />
    </targets>
    <rules>
      <!--<logger levels="Info,Warn,Error" writeTo="fileTarget" />-->
      <logger levels="Trace,Debug,Info,Warn,Error" writeTo="fileTarget" />
    </rules>
  </nlog>

在 2013年8月29日星期四UTC+8下午4时12分59秒，Kim Christensen写道：

[Kim Christensen]

Thanks I'll take a look at it, could you create an issue at github?