Log4j: Events appear in the wrong logfile

Question

Hi there!

To be able to log and trace some events I've added a LoggingHandler class to my java project. Inside this class I'm using two different log4j logger instances - one for logging an event and one for tracing an event into different files. The initialization block of the class looks like this:

public void initialize()
{
 System.out.print("starting logging server ...");

 // create logger instances
 logLogger = Logger.getLogger("log");
 traceLogger = Logger.getLogger("trace");

 // create pattern layout
 String conversionPattern = "%c{2} %d{ABSOLUTE} %r %p %m%n";
 try
 {
  patternLayout = new PatternLayout();
  patternLayout.setConversionPattern(conversionPattern);
 }
 catch (Exception e)
 {
  System.out.println("error: could not create logger layout pattern");
  System.out.println(e);
  System.exit(1);
 }

 // add pattern to file appender
 try
 {
  logFileAppender = new FileAppender(patternLayout, logFilename, false);
  traceFileAppender = new FileAppender(patternLayout, traceFilename, false);
 }
 catch (IOException e)
 {
  System.out.println("error: could not add logger layout pattern to corresponding appender");
  System.out.println(e);
  System.exit(1);
 }

 // add appenders to loggers
 logLogger.addAppender(logFileAppender);
 traceLogger.addAppender(traceFileAppender);

 // set logger level
 logLogger.setLevel(Level.INFO);
 traceLogger.setLevel(Level.INFO);

 // start logging server
 loggingServer = new LoggingServer(logLogger, traceLogger, serverPort, this);
 loggingServer.start();

 System.out.println(" done");
}

To make sure that only only thread is using the functionality of a logger instance at the same time each logging / tracing method calls the logging method .info() inside a synchronized-block. One example looks like this:

    public void logMessage(String message)
{
 synchronized (logLogger)
 {
  if (logLogger.isInfoEnabled() && logFileAppender != null)
  {
   logLogger.info(instanceName + ": " + message);
  }
 }
}

If I look at the log files, I see that sometimes a event appears in the wrong file. One example:

trace 10:41:30,773 11080 INFO masterControl(192.168.2.21): string broadcast message was  pushed from 1267093 to vehicle 1055293 (slaveControl 1)
trace 10:41:30,784 11091 INFO masterControl(192.168.2.21): string broadcast message was pushed from 1156513 to vehicle 1105792 (slaveControl 1)
trace 10:41:30,796 11103 INFO masterControl(192.168.2.21): string broadcast message was pushed from 1104306 to vehicle 1055293 (slaveControl 1)
trace 10:41:30,808 11115 INFO masterControl(192.168.2.21): vehicle 1327879 was pushed to slave control 1
10:41:30,808 11115 INFO masterControl(192.168.2.21): string broadcast message was pushed from 1101572 to vehicle 106741 (slaveControl 1)
trace 10:41:30,820 11127 INFO masterControl(192.168.2.21): string broadcast message was pushed from 1055293 to vehicle 1104306 (slaveControl 1)

I think that the problem occures everytime two event happen at the same time (here: 10:41:30,808). Does anybody has an idea how to solve my problem? I already tried to add a sleep() after the method call, but that doesn't helped ...

BR,

Markus

Edit:

logtrace  11:16:07,75511:16:07,755  1129711297  INFOINFO  masterControl(192.168.2.21): string broadcast message was pushed from 1291400 to vehicle 1138272 (slaveControl 1)masterControl(192.168.2.21): vehicle 1333770 was added to slave control 1

or

log 11:16:08,562 12104 INFO 11:16:08,562 masterControl(192.168.2.21): string broadcast message was pushed from 117772 to vehicle 1217744 (slaveControl 1)

12104 INFO masterControl(192.168.2.21): vehicle 1169775 was pushed to slave control 1

Edit 2:

It seems like the problem only occurs if logging methods are called from inside a RMI thread (my client / server exchange information using RMI connections). ...

Edit 3:

I solved the problem by myself: It seems like log4j is NOT completely thread-save. After synchronizing all log / trace methods using a separate object everything is working fine. Maybe the lib is writing the messages to a thread-unsafe buffer before writing them to file?

Answer 1

You don't need to synchronize on your logger but on the output stream.

If you use log4j, the output should be correctly synchronized. The only way to get what you see is that two threads write to the same file at the same time.

Is it possible that you configured two appenders with the same output file? Don't do that; every appender must have it's own, distinct file name.

If you're 100% sure that every appender writes to a different file, the only option left is that you're sometimes using the wrong logger.

Answer 2

Could it be that somehow the initialize method is called more than once? Every call would add two new appenders that write into the same file as the existing appenders.