Log4Net RollingFileAppender not flushing IO buffer with low volume log

Question

I'm pondering on the same issue as HENRI COOK did. It's been reported as a bug on Apache Jira as far as we can tell from the short description.

My problem in essence is that events are only logged when the application is shut down (even weeks after the event). That happens when logging volume is very low. I'm seeing this on a Windows Server 2008 R2. This prevents us from capturing and reacting to production errors.

Now the appender is not a buffering one. By default it also calls Flush() on the underlying stream every time a message is appended.

My question is WHY is it not flushing? And is there any remedy besides programatically flushing all appenders? Would you consider a pulsing appender a viable workaround?

The appender config:

<appender name="RollingErrorFileAppender" type="log4net.Appender.RollingFileAppender">
  <param name="File" value="D:\LogFiles\zzzz\xxxxxx__ERROR" />
  <param name="AppendToFile" value="true" />
  <param name="DatePattern" value="_yyyyMMddHH&quot;.log&quot;" />
  <param name="RollingStyle" value="Date" />
  <param name="StaticLogFileName" value="false" />
  <filter type="log4net.Filter.LevelRangeFilter">
    <param name="LevelMin" value="ERROR" />
    <param name="LevelMax" value="FATAL" />
  </filter>
  <layout type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%utcdate{yyyy-MM-dd HH:mm:ss.fff},[%thread],%level,%logger,%m%n"/>
  </layout>
</appender>

UPDATE 2013-06-19

I haven't been able to reproduce the behavior with any code. No matter how bad I try, the data is always written to the disk immediately. However, an important observation was made: If the first write to a file is larger than 1KiB, the modified-time is never updated with subsequent writes. It will only be updated when the file is closed with the time of closure. If on the other hand the first write is a short one-liner, any subsequent write will update the modified-time. This behavior is consistent between log4net and manual IO operation, between 32bit WinXP and 64bit W2k8R2, between .NET 2.0, 3.5 and .NET 4.0. That doesn't solve the problem still, but at least I can understand the strange modification-time pattern now.

Thanks, Rob

And to clarify, are you not seeing logs roll every hour when there has been at least one ERROR level or higher logging event during that period? I tested with your appender and saw logs flush and roll properly. — Adam S, Feb 25 '13 at 15:53
@AdamS, the problem usually manifests when 1) there are errors on application start-up and then the app stays quiet - no more log events come to roll the log. 2) If there is a subsequent log event beyond the roll period, the previous log file is flushed out (I presume since the IO stream is properly closed then). In either case 1 or 2, log events are delayed from reaching the file. — Robert Cutajar, Feb 27 '13 at 09:30

score 32 · Accepted Answer · edited Sep 01 '17 at 12:14

Since you are only concerned with error level or worse log events, and that traffic is fortunately infrequent, I would suggest configuring your appender to immediately flush.

<param name="ImmediateFlush" value="true" />

This saves you from having to programmatically flush your appender on every log event (which wasn't working anyway from the sound of it). Now, if you wish to open your appender up to more log levels, then of course immediately flushing all events could have greater performance concerns.

EDIT

I added the config file and a simple main program I used for testing. Using the following, I do see log events immediately flushed. In regard to your comment, I can also strip out the ImmediateFlush line from the xml and see the default true value work for flushing. I kept the line in my example for purposes of explicitly stating the desired behavior.

Basic main prog:

class Program
{
    static void Main(string[] args)
    {
        ILog log = LogManager.GetLogger(typeof(Program));
        XmlConfigurator.Configure(new FileInfo(@"C:\temp\logTest.config"));

        string msg;
        while ((msg = Console.ReadLine()) != "Done")
        {
            log.Error(msg);
        }

        LogManager.Shutdown();
    }
}

logTest.config referenced by main prog:

<log4net>
    <appender name="RollingErrorFileAppender" type="log4net.Appender.RollingFileAppender">
        <param name="File" value="C:\temp\log" />
        <param name="AppendToFile" value="true" />
        <param name="DatePattern" value="_yyyyMMddHH&quot;.log&quot;" />
        <param name="RollingStyle" value="Date" />
        <param name="StaticLogFileName" value="false" />
        <param name="ImmediateFlush" value="true" />
        <filter type="log4net.Filter.LevelRangeFilter">
            <param name="LevelMin" value="ERROR" />
            <param name="LevelMax" value="FATAL" />
        </filter>
        <layout type="log4net.Layout.PatternLayout">
            <param name="ConversionPattern" value="%utcdate{yyyy-MM-dd HH:mm:ss.fff},[%thread],%level,%logger,%m%n"/>
        </layout>
    </appender>
    <root>
        <level value="INFO" />
        <appender-ref ref="RollingErrorFileAppender" />
    </root>
</log4net>

Thanks @AdamS, though I dare to disagree. If you peek at the code of `private bool m_immediateFlush = true;` and `override protected void Append(LoggingEvent loggingEvent)` in [v1.2.10 TextWriterAppender](http://svn.apache.org/viewvc/logging/log4net/tags/log4net-1.2.10/src/Appender/TextWriterAppender.cs?view=markup) , you'll agree with me that ImmediateFlush is true by default and so the appender actually calls Flush() on each Append() as I already said in the Q. — Robert Cutajar, Mar 20 '13 at 16:29
Edited my answer with the test program I used. With that I can see events immediately flushed. Do you not see the same behavior? — Adam S, Mar 29 '13 at 16:20
Thanks AdamS, that's a great idea. I'll try tomorrow hopefully. — Robert Cutajar, Apr 03 '13 at 19:15
AdamS, I've updated the Q - UPDATE 2013-06-19. I appreciate the effort you've put into this so far. I guess an acceptable answer really could sound "If you cannot reproduce it, it's not a bug" :D I'm starting to suspect there might be an issue in the alert collector after all. — Robert Cutajar, Jun 19 '13 at 22:01
Resolved! It was both W2k8 and our log parsing tool. W2k8 came with delayed modification time updates "feature" : http://blogs.technet.com/b/asiasupp/archive/2010/12/14/file-date-modified-property-are-not-updating-while-modifying-a-file-without-closing-it.aspx And our tool was removing log file checkpoints after 3 days. Together, this created a false feeling and confusion that logging was delayed. The reproduced behavior is that modification is not updated until the file write handle is closed UNLESS the first write is tiny, then it is updated on every subsequent write. Weird feature that is — Robert Cutajar, Jul 18 '13 at 10:24
I'll summarize the problem: When you log some line to log you expect that the line will appear there immediately and cause file growth but this doesn't happen and you think that flush doesn't work. You press F5 in explorer again and again but file size remains the same. Solution? Access file handle by other application. For me works just right mouse click on the file. — Pavel Shkleinik, Oct 19 '13 at 11:10

Log4Net RollingFileAppender not flushing IO buffer with low volume log

1 Answers1

Linked