You are viewing a plain text version of this content. The canonical link for it is here.
Posted to general@logging.apache.org by je...@ca.ibm.com on 2005/09/15 04:44:49 UTC
multi thread log corruption
Hi all,
I have a little problem. I read that log4j is thread-safe in the
manual. I have a mutlthreaded environnement. I have a base class that I
launch, that is launching many threads depending on a configuration file.
Each of those threads are named with a name that represent the Runnable
class that is start in a new thread. I would like to a a log file that logs
EVERY event, and 1 log file per differents names of the thread.
Ex: base class launch 3 threads of type A, 5 threads of type B and 1 thread
of class C =
1 log file for the base class that will also logs type A, B, C event,
1 log file for threads of type A (3 threads write in it)
1 log file for threads of type B (5 threads write in it)
1 log file for threads of type C (1 thread write in it)
So I based myself on a ThreadFileAppender that I found with the help of
google. Here is the code:
public class ThreadFileAppender extends AppenderSkeleton {
private final HashMap outStreamCache;
/**
* Immediate flush means that the underlying writer or output stream
* will be flushed at the end of each append operation. Immediate
* flush is slower but ensures that each append request is actually
* written. If <code>immediateFlush</code> is set to
* <code>false</code>, then there is a good chance that the last few
* logs events are not actually written to persistent media if and
* when the application crashes.<p>
*
* The <code>immediateFlush</code> variable is set to
* <code>true</code> by default.
*/
private boolean immediateFlush = true;
/**
* The name of the log file.
*/
private String fileName;
/**
* Append to or truncate the file? The default value for this
* variable is <code>true</code>, meaning that by default this
* will append to an existing file and not truncate it.
*/
private boolean fileAppend = true;
public ThreadFileAppender() {
super();
outStreamCache = new HashMap();
}
/**
* If the <b>ImmediateFlush</b> option is set to
* <code>true</code>, the appender will flush at the end of each
* write. This is the default behavior. If the option is set to
* <code>false</code>, then the underlying stream can defer writing
* to physical medium to a later time.
*
* <p>Avoiding the flush operation at the end of each append results
in
* a performance gain of 10 to 20 percent. However, there is safety
* tradeoff involved in skipping flushing. Indeed, when flushing is
* skipped, then it is likely that the last few log events will not
* be recorded on disk when the application exits. This is a high
* price to pay even for a 20% performance gain.
*
* @param value
*/
public void setImmediateFlush(boolean value) {
immediateFlush = value;
}
/**
* Returns value of the <b>ImmediateFlush</b> option.
*/
public boolean getImmediateFlush() {
return immediateFlush;
}
/**
* The <b>File</b> option takes a string value which should be
* the name of the file to append to. Special values "System.out" or
* "System.err" are interpreted as the standard out and standard
* error streams.<p>
*
* Note: Actual opening of the file is made when {@link
* #subAppend(LogEvent)} is called, not when the options are set.
*
* @param file
*/
public void setFileName(String file) {
// Trim spaces from both ends. The users probably does not want
// trailing spaces in file names.
fileName = file.trim();
}
/**
* Returns the value of the <b>FileName</b> option.
*/
public String getFileName() {
return fileName;
}
/**
* The <b>Append</b> option takes a boolean value. It is set to
* <code>true</code> by default. If true, then <code>File</code>
* will be opened in append mode by {@link #setFileName(String)}.
* Otherwise, {@link #setFileName(String) will open
* <code>File</code> in truncate mode.<p>
*
* Note: Actual opening of the file is made when {@link
* #subAppend(LogEvent)} is called, not when the options are set.
*/
public void setAppend(boolean flag) {
fileAppend = flag;
}
/**
* Returns the value of the <b>Append</b> option.
*/
public boolean getAppend() {
return fileAppend;
}
/**
* Does nothing.
*/
public void activateOptions() {
}
/**
* This method is called by the {@link AppenderSkeleton#doAppend}
* method.<p>
*
* If the output stream exists and is writable then write a log
* statement to the output stream. Otherwise, write a single warning
* message to <code>System.err</code>.<p>
*
* The format of the output will depend on this appender's
* layout.
*
* @param event
*/
public void append(LoggingEvent event) {
if (!checkEntryConditions()) {
return;
}
subAppend(event);
}
/**
* This method determines if there is a sense in attempting to
append.<p>
*
* It checks whether there is a set output target and also if
* there is a set layout. If these checks fail, then the boolean
* value <code>false</code> is returned.
*/
protected boolean checkEntryConditions() {
if (closed) {
LogLog.warn("Not allowed to write to a closed
appender.");
return false;
}
if (layout == null) {
errorHandler.error("No layout set for the appender
named["+getName()+"].");
return false;
}
return true;
}
/**
* Actual writing occurs here.
*/
protected void subAppend(LoggingEvent event) {
try {
String threadName = event.getThreadName();
Writer out = (Writer)outStreamCache.get(threadName);
if (out == null) {
out = new BufferedWriter(new
FileWriter(getFileName()+"."+threadName+".log", getAppend()));
writeHeader(out);
outStreamCache.put(threadName, out);
}
out.write(layout.format(event));
if (layout.ignoresThrowable()) {
String[] s = event.getThrowableStrRep();
if (s != null) {
int len = s.length;
for (int i = 0; i < len; i++) {
out.write(s[i]);
out.write(Layout.LINE_SEP);
}
}
}
if (immediateFlush) {
out.flush();
}
} catch (FileNotFoundException exp) {
LogLog.error("Could not find
file:"+getFileName()+"."+event.getThreadName()+".log", exp);
} catch (IOException exp) {
LogLog.error("Could write to
file:"+getFileName()+"."+event.getThreadName()+".log", exp);
}
}
/**
* Close this appender instance. The underlying writers are
* also closed.<p>
*
* Closed appenders cannot be reused.
*/
public synchronized void close() {
if (closed)
return;
closed = true;
writeFooters();
reset();
}
/**
* Clear internal references to the writer and other variables.<p>
*
* Subclasses can override this method for an alternate closing
* behavior.
*/
protected void reset() {
Iterator iter = outStreamCache.values().iterator();
while (iter.hasNext()) {
try {
((Writer)iter.next()).close();
} catch (IOException exp) {
LogLog.error("Couldn't close writer", exp);
}
}
}
/**
* The ThreadFileAppender requires a layout. Hence, this method
returns
* <code>true</code>.
*
* @return true
*/
public boolean requiresLayout() {
return true;
}
/**
* Write a footer as produced by the embedded layout's {@link
* Layout#getFooter} method.
*/
private void writeFooters() {
if (layout != null) {
String f = layout.getFooter();
if (f != null) {
Iterator iter = outStreamCache.values().iterator();
while (iter.hasNext()) {
try {
((Writer)iter.next()).write(f);
} catch (IOException exp) {
LogLog.error("Couldn't write footer",
exp);
}
}
}
}
}
/**
* Write a header as produced by the embedded layout's {@link
* Layout#getHeader} method.
*/
private void writeHeader(Writer out) {
if (layout != null) {
String h = layout.getHeader();
if (h != null) {
if (layout != null) {
String f = layout.getFooter();
if (f != null) {
try {
out.write(f);
} catch (IOException exp) {
LogLog.error("Couldn't write
footer", exp);
}
}
}
}
}
}
/**
* Test the class
*/
public static void main(String[] argv) {
// Initialisation de log4j avec le bon fichier de propriété.
PropertyConfigurator.configure(Thread.currentThread().getContextClassLoader().getResource("log4j_JUnit.properties"));
Logger logger = Logger.getRootLogger();
ThreadFileAppender appender = new ThreadFileAppender();
appender.setFileName("MSI");
appender.setLayout(new SimpleLayout());
logger.addAppender(appender);
for (int i=0; i < 5; i++) {
(new Thread() {
public void run() {
Logger.getRootLogger().warn("Hello from "+this);
}
}).start();
}
(new Thread("NamedThread") {
public void run() {
Logger.getRootLogger().warn("First line");
Logger.getRootLogger().warn("Second line");
}
}).start();
(new Thread("NamedThread") {
public void run() {
Logger.getRootLogger().warn("Third line");
}
}).start();
}
}
Here is how I define my appenders in the base class:
public static Logger log =Logger.getRootLogger();
static {
// Initialisation de log4j avec le bon fichier de propriété.
PropertyConfigurator.configure(Thread.currentThread().getContextClassLoader().getResource(LOG4J_PROPERTY_FILENAME));
ThreadFileAppender threadFileAppender = new
ThreadFileAppender();
threadFileAppender.setFileName("MSI");
threadFileAppender.setLayout(Logger.getRootLogger().getAppender("A1").getLayout());
threadFileAppender.activateOptions();
log.addAppender(threadFileAppender);
}
Here is my configuration file:
# Set root logger's level and its appender
log4j.rootLogger=DEBUG, A1, A2
log4j.appender.A1=org.apache.log4j.RollingFileAppender
log4j.appender.A1.File=diagnostic.log
log4j.appender.A1.MaxFileSize=5MB
log4j.appender.A1.MaxBackupIndex=2
log4j.appender.A1.layout=org.apache.log4j.PatternLayout
log4j.appender.A1.layout.ConversionPattern=[%d{ISO8601}]%-5p [%-20t] ->
%m%n
log4j.appender.A1.BufferSize=2048
log4j.appender.A1.BufferedIO=true
log4j.appender.A2=org.apache.log4j.ConsoleAppender
log4j.appender.A2.layout=org.apache.log4j.PatternLayout
log4j.appender.A2.layout.ConversionPattern=[%d{ISO8601}]%-5p [%-20t] ->
%m%n
I've been able to setup all this. But I have log corruption in the log
files of the threads. The log file of the base class is OK. Here is a
sample of corruption:
[2005-09-14 22:15:20,328]INFO [CheckMcs2TrxServer ] -> LogEvent1
[2005-09-14 22:15:20,344]INFO [CheckMcs2TrxServer ] -> 2005-09-14
22:15:20,328]LogEvent2
INFO[2005-09-14 22:15:20,344]INFO [CheckMcs2TrxServer ] -> LogEvent3
[2005-09-14 22:15:20,344]INFO [CheckMcs2TrxServer ] -> LogEvent4
[2005-09-14 22:15:21,625]INFO [CheckMcs2TrxServer ] -> LogEvent5
I don't understand this problem. Each call of my subAppend() function in my
ThreadFileAppender is theorically synchronized, as the doAppend() function
in the AppenderSkeleton is synchronized.
Any idea anyone?
-----------------------------------------------------------------------------
Jean-Francois Croteau
Re: multi thread log corruption
Posted by Curt Arnold <ca...@apache.org>.
On Sep 14, 2005, at 9:44 PM, jecrotea@ca.ibm.com wrote:
>
> Hi all,
> I have a little problem. I read that log4j is thread-safe in the
> manual. I have a mutlthreaded environnement. I have a base class
> that I
> launch, that is launching many threads depending on a configuration
> file.
> Each of those threads are named with a name that represent the
> Runnable
> class that is start in a new thread. I would like to a a log file
> that logs
> EVERY event, and 1 log file per differents names of the thread.
>
> Ex: base class launch 3 threads of type A, 5 threads of type B and
> 1 thread
> of class C =
> 1 log file for the base class that will also logs type A, B,
> C event,
> 1 log file for threads of type A (3 threads write in it)
> 1 log file for threads of type B (5 threads write in it)
> 1 log file for threads of type C (1 thread write in it)
>
> So I based myself on a ThreadFileAppender that I found with the
> help of
> google. Here is the code:
Logging-general is designed for conversations involving more that one
LS project. For example, a discussion about compatibility between
log4cxx and log4j, would be an appropriate topic for logging-general.
For questions regarding use of log4j, log4j-user would be the
appropriate forum. However, as far as I can tell from your message,
you are not having problems with log4j, but with a custom appender
that you found somewhere on the net. If so, it would be best to
contact the author of the appender.