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?