[ https://issues.apache.org/jira/browse/LOG4J2-254?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13658455#comment-13658455 ]
Remko Popma commented on LOG4J2-254: ------------------------------------ Improvements (1) and (3) are now committed to trunk. > 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 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