logging-log4j-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Remko Popma (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (LOG4J2-254) Race condition when setting new filename in RollingFileAppender related code
Date Wed, 15 May 2013 13:05:23 GMT

    [ https://issues.apache.org/jira/browse/LOG4J2-254?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13658330#comment-13658330

Remko Popma commented on LOG4J2-254:

Nick, I think you are right. Updating the field after writing the header is better.
> Race condition when setting new filename in RollingFileAppender related code
> ----------------------------------------------------------------------------
>                 Key: LOG4J2-254
>                 URL: https://issues.apache.org/jira/browse/LOG4J2-254
>             Project: Log4j 2
>          Issue Type: Bug
>          Components: Appenders
>    Affects Versions: 2.0-beta7
>            Reporter: Edward Sargisson
>             Fix For: 2.0-beta7
> I've come across what very much looks like a race condition in log4j1. In reviewing the
log4j 2 code I believe the same condition exists.
> OutputStreamManager.setOutputStream and OutputStreamManager.write need to have a happens-before
edge inserted. You could either make OutputStreamManager.os volatile (best) or make setOutputStream
> When the RollingFileAppender decides to roll the file it creates a new OutputStream and
calls setOutputStream with it. If there is no happens-before edge then that write to OutputStreamManager.os
may not be visible to all threads.
> Background:
> I've been attempting to find a way to have applications write logs to Flume without being
halted if Flume is down or its channels fill up. My approach was to use the RollingFileAppender
from apache-log4j-extras and configure it to roll every minute. Then I setup a Flume spooling
directory source to read those files and forward them on.
> I've been having problems with Flume complaining that the rolled log file has changed.
The spooling directory source checks this so that people do not attempt to use it on logs
that are currently being written to.
> I caught an instance of this this afternoon.
> File: castellan-reader.20130514T2058.log.COMPLETED
> 2013-05-14 20:57:05,330  INFO ...
> File: castellan-reader.20130514T2058.log
> 2013-05-14 21:23:05,709 DEBUG ...
> Why would an event from 2123 be written into a file from 2058?
> My analysis of log4j 1 code is:
> My understanding of log4j shows that the RollingFileAppenders end up calling this:
> FileAppender:
> public  synchronized  void setFile(String fileName, boolean append, boolean bufferedIO,
int bufferSize)
> Which shortly calls:
> this.qw = new QuietWriter(writer, errorHandler);
> However, the code to actually write to the writer is this:
> protected
>   void subAppend(LoggingEvent event) {
>     this.qw.write(this.layout.format(event));
> Unless I'm mistaken there's no happens-before edge between setting the qw and calling
subappend. The code path to get to subAppend appears not to go through any method synchronized
on FileAppender's monitor. this.qw is not volatile.
> Note that I haven't tested log4j 2 for this probable defect - I am raising this work
item based on my reading of the code.

This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira

To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org

View raw message