logging-general mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From jecro...@ca.ibm.com
Subject multi thread log corruption
Date Thu, 15 Sep 2005 02:44:49 GMT

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




Mime
View raw message