[
https://issues.apache.org/jira/browse/LOG4J2-254?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13658323#comment-13658323
]
Remko Popma commented on LOG4J2-254:
------------------------------------
Gary, there is a subtle difference. It is hard to see from just the code
snippet, so here is the method in full:
protected void setOutputStream(final OutputStream os) {
this.os = os; // replace value of volatile field
if (header != null) {
try {
this.os.write(header, 0, header.length); // volatile field
value may have changed again...
} catch (final IOException ioe) {
LOGGER.error("Unable to write header", ioe);
}
}
}
Now, imagine a multithreaded scenario where threads t1 and t2 access this
method at the same time.
One possible sequence of events would be:
[t1] this.os = os; // os is now os1
[t2] this.os = os; // os is now os2
[t1] this.os.write(header, 0, header.length); // t1 writes header to os2
[t2] this.os.write(header, 0, header.length); // t2 writes the same header to
os2 again
In this scenario os1 has no headers written to it and os2 has the same header
written to it twice.
The solution is to call the write method on the *local* parameter os, not on
the field.
In general, within the same method a volatile field should only be accessed
*once*. Anything else is suspicious.
(Usage of the volatile field "config" in core.Logger violates this rule of
thumb, but that is by design.)
> 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
