From general-return-604-apmail-logging-general-archive=logging.apache.org@logging.apache.org Thu Sep 15 02:44:50 2005 Return-Path: Delivered-To: apmail-logging-general-archive@www.apache.org Received: (qmail 91967 invoked from network); 15 Sep 2005 02:44:50 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (209.237.227.199) by minotaur.apache.org with SMTP; 15 Sep 2005 02:44:50 -0000 Received: (qmail 75019 invoked by uid 500); 15 Sep 2005 02:44:49 -0000 Delivered-To: apmail-logging-general-archive@logging.apache.org Received: (qmail 74968 invoked by uid 500); 15 Sep 2005 02:44:48 -0000 Mailing-List: contact general-help@logging.apache.org; run by ezmlm Precedence: bulk list-help: list-unsubscribe: List-Post: Reply-To: "Logging General" List-Id: Delivered-To: mailing list general@logging.apache.org Received: (qmail 74955 invoked by uid 99); 15 Sep 2005 02:44:48 -0000 Received: from asf.osuosl.org (HELO asf.osuosl.org) (140.211.166.49) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 14 Sep 2005 19:44:48 -0700 X-ASF-Spam-Status: No, hits=1.0 required=10.0 tests=DNS_FROM_RFC_ABUSE,NO_REAL_NAME,SPF_HELO_FAIL X-Spam-Check-By: apache.org Received-SPF: pass (asf.osuosl.org: local policy) Received: from [32.97.182.144] (HELO e4.ny.us.ibm.com) (32.97.182.144) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 14 Sep 2005 19:44:59 -0700 Received: from d01relay02.pok.ibm.com (d01relay02.pok.ibm.com [9.56.227.234]) by e4.ny.us.ibm.com (8.12.11/8.12.11) with ESMTP id j8F2ikXm007312 for ; Wed, 14 Sep 2005 22:44:46 -0400 Received: from d01av02.pok.ibm.com (d01av02.pok.ibm.com [9.56.224.216]) by d01relay02.pok.ibm.com (8.12.10/NCO/VERS6.7) with ESMTP id j8F2ikaD091990 for ; Wed, 14 Sep 2005 22:44:46 -0400 Received: from d01av02.pok.ibm.com (loopback [127.0.0.1]) by d01av02.pok.ibm.com (8.12.11/8.13.3) with ESMTP id j8F2ikPW018285 for ; Wed, 14 Sep 2005 22:44:46 -0400 Received: from brmoe1.bromont.ibm.com (brmoesy3.bromont.ibm.com [9.54.4.225]) by d01av02.pok.ibm.com (8.12.11/8.12.11) with ESMTP id j8F2ikcN018281 for ; Wed, 14 Sep 2005 22:44:46 -0400 Subject: multi thread log corruption To: general@logging.apache.org X-Mailer: Lotus Notes Release 6.0.2CF1 June 9, 2003 Message-ID: From: jecrotea@ca.ibm.com Date: Wed, 14 Sep 2005 22:44:49 -0400 X-MIMETrack: Serialize by Router on brmoe1/Bromont(Release 6.5.4FP1 LVAE67PJ3Q SFPN69ET56 TCHL62QQ9D|July 26, 2005) at 09/14/2005 22:44:45 MIME-Version: 1.0 Content-type: text/plain; charset=ISO-8859-1 Content-transfer-encoding: quoted-printable X-Virus-Checked: Checked by ClamAV on apache.org X-Spam-Rating: minotaur.apache.org 1.6.2 0/1000/N 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 fil= e. 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 th= read of class C =3D 1 log file for the base class that will also logs type A, B, C ev= ent, 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 str= eam * will be flushed at the end of each append operation. Immediate= * flush is slower but ensures that each append request is actual= ly * written. If immediateFlush is set to * false, then there is a good chance that the last = few * logs events are not actually written to persistent media if an= d * when the application crashes.

* * The immediateFlush variable is set to * true by default. */ private boolean immediateFlush =3D true; /** * The name of the log file. */ private String fileName; /** * Append to or truncate the file? The default value for this * variable is true, meaning that by default this * will append to an existing file and not truncate it. */ private boolean fileAppend =3D true; public ThreadFileAppender() { super(); outStreamCache =3D new HashMap(); } /** * If the ImmediateFlush option is set to * true, the appender will flush at the end of each * write. This is the default behavior. If the option is set to * false, then the underlying stream can defer writi= ng * to physical medium to a later time. * *

Avoiding the flush operation at the end of each append resu= lts in * a performance gain of 10 to 20 percent. However, there is safe= ty * tradeoff involved in skipping flushing. Indeed, when flushing = is * skipped, then it is likely that the last few log events will n= ot * 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 =3D value; } /** * Returns value of the ImmediateFlush option. */ public boolean getImmediateFlush() { return immediateFlush; } /** * The File 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.

* * 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 =3D file.trim(); } /** * Returns the value of the FileName option. */ public String getFileName() { return fileName; } /** * The Append option takes a boolean value. It is set to * true by default. If true, then File * will be opened in append mode by {@link #setFileName(String)}.= * Otherwise, {@link #setFileName(String) will open * File in truncate mode.

* * 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 =3D flag; } /** * Returns the value of the Append option. */ public boolean getAppend() { return fileAppend; } /** * Does nothing. */ public void activateOptions() { } /** * This method is called by the {@link AppenderSkeleton#doAppend}= * method.

* * If the output stream exists and is writable then write a log * statement to the output stream. Otherwise, write a single warn= ing * message to System.err.

* * 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.

* * 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 false is returned. */ protected boolean checkEntryConditions() { if (closed) { LogLog.warn("Not allowed to write to a closed appender."); return false; } if (layout =3D=3D 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 =3D event.getThreadName(); Writer out =3D (Writer)outStreamCache.get(threadName)= ; if (out =3D=3D null) { out =3D new BufferedWriter(new FileWriter(getFileName()+"."+threadName+".log", getAppend())); writeHeader(out); outStreamCache.put(threadName, out); } out.write(layout.format(event)); if (layout.ignoresThrowable()) { String[] s =3D event.getThrowableStrRep(); if (s !=3D null) { int len =3D s.length; for (int i =3D 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.

* * Closed appenders cannot be reused. */ public synchronized void close() { if (closed) return; closed =3D true; writeFooters(); reset(); } /** * Clear internal references to the writer and other variables. * * Subclasses can override this method for an alternate closing * behavior. */ protected void reset() { Iterator iter =3D 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 * true. * * @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 !=3D null) { String f =3D layout.getFooter(); if (f !=3D null) { Iterator iter =3D outStreamCache.values().itera= tor(); 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 !=3D null) { String h =3D layout.getHeader(); if (h !=3D null) { if (layout !=3D null) { String f =3D layout.getFooter(); if (f !=3D 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=E9= t=E9. PropertyConfigurator.configure(Thread.currentThread().getContextClassLo= ader().getResource("log4j_JUnit.properties")); Logger logger =3D Logger.getRootLogger(); ThreadFileAppender appender =3D new ThreadFileAppender(); appender.setFileName("MSI"); appender.setLayout(new SimpleLayout()); logger.addAppender(appender); for (int i=3D0; 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 =3DLogger.getRootLogger(); static { // Initialisation de log4j avec le bon fichier de propri=E9= t=E9. PropertyConfigurator.configure(Thread.currentThread().getContextClassLo= ader().getResource(LOG4J_PROPERTY_FILENAME)); ThreadFileAppender threadFileAppender =3D new ThreadFileAppender(); threadFileAppender.setFileName("MSI"); threadFileAppender.setLayout(Logger.getRootLogger().getAppender("A1").g= etLayout()); threadFileAppender.activateOptions(); log.addAppender(threadFileAppender); } Here is my configuration file: # Set root logger's level and its appender log4j.rootLogger=3DDEBUG, A1, A2 log4j.appender.A1=3Dorg.apache.log4j.RollingFileAppender log4j.appender.A1.File=3Ddiagnostic.log log4j.appender.A1.MaxFileSize=3D5MB log4j.appender.A1.MaxBackupIndex=3D2 log4j.appender.A1.layout=3Dorg.apache.log4j.PatternLayout log4j.appender.A1.layout.ConversionPattern=3D[%d{ISO8601}]%-5p [%-20t] = -> %m%n log4j.appender.A1.BufferSize=3D2048 log4j.appender.A1.BufferedIO=3Dtrue log4j.appender.A2=3Dorg.apache.log4j.ConsoleAppender log4j.appender.A2.layout=3Dorg.apache.log4j.PatternLayout log4j.appender.A2.layout.ConversionPattern=3D[%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 i= n my ThreadFileAppender is theorically synchronized, as the doAppend() funct= ion in the AppenderSkeleton is synchronized. Any idea anyone? -----------------------------------------------------------------------= ------ Jean-Francois Croteau =