19

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

3
  • Can you post the config for the appender you are using?
    – Adam S
    Commented Feb 20, 2013 at 18:08
  • 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
    Commented Feb 25, 2013 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. Commented Feb 27, 2013 at 9:30

1 Answer 1

32

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>
6
  • 1
    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 , 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. Commented Mar 20, 2013 at 16:29
  • 1
    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
    Commented Mar 29, 2013 at 16:20
  • Thanks AdamS, that's a great idea. I'll try tomorrow hopefully. Commented Apr 3, 2013 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. Commented Jun 19, 2013 at 22:01
  • 7
    Resolved! It was both W2k8 and our log parsing tool. W2k8 came with delayed modification time updates "feature" : blogs.technet.com/b/asiasupp/archive/2010/12/14/… 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 Commented Jul 18, 2013 at 10:24

Not the answer you're looking for? Browse other questions tagged or ask your own question.