Log4Net RollingFileAppender not flushing IO buffer with low volume log

Rbjz picture Rbjz · Feb 19, 2013 · Viewed 26.1k times · Source

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

Answer

Adam S picture Adam S · Feb 27, 2013

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>