[
https://issues.apache.org/jira/browse/LOG4J2-254?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13667343#comment-13667343
]
Ralph Goers commented on LOG4J2-254:
------------------------------------
Thanks for catching that! Fix was applied in revision 1486421.
> 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
> Priority: Blocker
> 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 synchronized.
> 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-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
