Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Log4Net RollingFileAppender not flushing IO buffer with low volume log

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

like image 655
Robert Cutajar Avatar asked Feb 19 '13 17:02

Robert Cutajar


People also ask

What is RollingFileAppender in log4net?

RollingFileAppender means the system creates a log file based on your filters, this way you can have log files based on dates (one file each day), or get the file splitted into small chunks when it hits certain size.

Where are log4net logs stored?

You can configure the log4net. config file to create log files. The file is located in the webroot\App_data directory of the installation. The different log files are described in Services logs.

Is log4net thread safe?

Is log4net thread-safe? Yes, log4net is thread-safe.


Video Answer


1 Answers

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>
like image 155
Adam S Avatar answered Sep 16 '22 15:09

Adam S