[
https://issues.apache.org/jira/browse/LOG4J2-254?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Edward Sargisson reopened LOG4J2-254:
-------------------------------------
This code doesn't work the second time the file rolls. I get the following
stack trace:
2013-05-22 22:24:09,522 ERROR Unable to write to stream
/var/log/flume-ng/flume.log for appender RollingFile
2013-05-22 22:24:09,522 ERROR An exception occurred processing Appender
RollingFile org.apache.logging.log4j.core.appender.AppenderRuntimeException:
Error flushing stream /var/log/flume-ng/flume.log
at
org.apache.logging.log4j.core.appender.OutputStreamManager.flush(OutputStreamManager.java:150)
at
org.apache.logging.log4j.core.appender.AbstractOutputStreamAppender.append(AbstractOutputStreamAppender.java:115)
at
org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:84)
at
org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:102)
at
org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:404)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:385)
at
org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:346)
at org.apache.logging.log4j.core.Logger.log(Logger.java:110)
at
org.apache.logging.log4j.spi.AbstractLoggerWrapper.log(AbstractLoggerWrapper.java:55)
at org.slf4j.impl.SLF4JLogger.warn(SLF4JLogger.java:311)
at
org.elasticsearch.common.logging.slf4j.Slf4jESLogger.internalWarn(Slf4jESLogger.java:104)
at
org.elasticsearch.common.logging.support.AbstractESLogger.warn(AbstractESLogger.java:100)
at
org.elasticsearch.client.transport.TransportClientNodesService$SimpleNodeSampler.sample(TransportClientNodesService.java:319)
at
org.elasticsearch.client.transport.TransportClientNodesService$ScheduledNodeSampler.run(TransportClientNodesService.java:281)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
Caused by: java.io.IOException: Stream Closed
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:318)
at
java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
at
org.apache.logging.log4j.core.appender.OutputStreamManager.flush(OutputStreamManager.java:147)
... 16 more
This is from a log4j2.xml with the following snippet:
<RollingFile name="RollingFile" fileName="/var/log/flume-ng/flume.log"
filePattern="/var/log/flume-ng/spool/flume.%d{yyyyMMdd'T'HHmm}.log">
<!-- date level [thread] logger message exception newline -->
<PatternLayout pattern="%d %5p [%t] %25c{1.} %m%xEx%n" />
<Policies>
<TimeBasedTriggeringPolicy />
</Policies>
<DefaultRolloverStrategy max="20"/>
</RollingFile>
> 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: [email protected]
For additional commands, e-mail: [email protected]
