Why are my Log4j log file timestamps out of order,

Question

My log4j.xml contains:

<appender class="org.jboss.logging.appender.RollingFileAppender" name="rm">
  ...
  </layout>

My log file shows timestamps that are out of order. Can we display based on timestamp?

2009-02-19 14:47:01,288 DEBUG [com.catalystwms.core.persistence.TransactionContext]  
2009-02-19 14:54:27,429 INFO [com.catalystwms.tms.services.background.purge.PurgeManager]  
2009-02-19 14:47:01,288 DEBUG [com.catalystwms.core.services.ServiceLocator] 

Please help me.

Thanks,

Answer 1

You have two different processes logging to the same log file with a rolling appender. Log4j does not allow this. In the past, I've resolved this in a clustered web app by adding a server name to the log file: appname-server1.log and appname-server2.log with each server configured to write to their own log.

This can also be useful to track down bugs that are specific to one machine's configuration vs. another.

All of the above also works if you have two different applications writing to the same log file by naming the files based on the application being executed.

Answer 2

The date format is designed to allow the a simple character based sort to order it correctly.

sort server.log | more

EDIT: This is useful for use on existing log files (not for configuring log4j).

Answer 3

Are the two log statements occurring on different threads.

(Thread 1) 2009-02-19 14:54:27,429 INFO [com.catalystwms.tms.services.background.purge.PurgeManager]
(Thread 2) 2009-02-19 14:47:01,288 DEBUG [com.catalystwms.core.services.ServiceLocator

I believe the log statements time accurrately gives the time when the event occurred but are just written out of order because thread 2 is waiting to get the lock. I believe wrapping your appender in a org.apache.log4j.AsyncAppender should fix the issue.

Answer 4

In response to @andy:
(Thread 1) 2009-02-19 14:54:27,429 INFO [com.catalystwms.tms.services.background.purge.PurgeManager]
(Thread 2) 2009-02-19 14:47:01,288 DEBUG [com.catalystwms.core.services.ServiceLocator

what i believe may be happening is thread 2 creates a logRecord at 14:47:01,288 when it attempts to write, it needs to get a lock for the Logger's list of appenders, but another thread has the lock and is busy doing IO so thread 2 waits. thread 1 creates logRecord at 14:54:27,429 it attempts to get the same lock and also waits. When the lock is freed the OS gives it to thread 1 and it prints.

If this is true the other big issue is one of performance. Code paths could block on logging IO.

Answer 5

You probably won't be able to fix it before the log is written. You could try modifying log4J to call .flush() after every write, but that will make your code a good deal slower and @Chris Nava's solution is more appropriate.