The call to wait in AsyncAppender.append() is surrounded by an if-statement to check the guard condition (bf.isFull()). The wait() should be enclosed inside of while(bf.isFull) { ... }. This is because interrupting the waiting will cause append to continue executing as if the condition were satisfied. In the case that the BufferedFIFO is still full, then the append will silently fail because the implementaiton of BufferedFIFO.put silently drops the event when the FIFO is full. At the end of this description is a program that forces this to happen. I have been able to consistently cause it to happen on my computer, a dual processor Pentium II 400Mhz running Windows NT 4.0, using both Log4j 1.0.4 and 1.1b5. This problem ought to be platform-independent, though. The following program causes the event lossage to occur for version 1.1b5 (for 1.0.4 replace event.getMessage() with event.message). Admittedly, it is only in pathological situations where it can occur, but the fix is simple. import java.lang.*; import java.util.*; import org.apache.log4j.*; import org.apache.log4j.performance.*; import org.apache.log4j.spi.*; /** * Program that attempts to cause AsyncAppender to have an event * lossed by it being silently dropped BufferedFIFO.put(). This can * occur when the FIFO is full and the AsyncAppender.append() * operation is interrupted while waiting. The ultimate cause of * the error is the failure to use a while-loop when waiting * in AsyncAppender.append(). * * <p>The main program repeated sends messages encoding increasing * long integer values. A second thread repeatedly invokes * interrupt on the main thread. A special Appender implementation * is used to check for missed events. If a received event is not * exactly 1 greater than the previous event then an event has been * dropped on the floor due to AysncAppender.append being interrupted. * * @author Aaron Greenhouse */ public class SkipEvent { /** Set to true when the error is detected. */ private static volatile boolean errorFound = false; /** * Flag used for busy-waiting so that we don't exit before * the error info is printing. */ private static volatile boolean donePrinting = false; public static void main( String[] args ) { final Category cat = Category.getInstance( "test_cat" ); final AsyncAppender aa = new AsyncAppender(); final CheckerAppender checker = new CheckerAppender(); aa.addAppender( checker ); cat.addAppender( aa ); final Thread interrupter = new Thread( new Interrupter( Thread.currentThread() ) ); interrupter.start(); // Repeated send ever increasing events. long message = 1L; while( !errorFound ) { cat.info( Long.toString( message ) ); message += 1; } // Shutdown try { interrupter.join(); } catch( InterruptedException e ) { } // Busy wait for the error info to print while( !donePrinting ) { Thread.yield(); } // Call exit because the thread in AysncAppender is not a // daemon thread. System.exit( 0 ); } /** * Repeatedly interrupt the given thread until the * error has been detected. */ private static class Interrupter implements Runnable { private final Thread victim; public Interrupter( final Thread v ) { victim = v; } public void run() { while( !errorFound ) { victim.interrupt(); } } } /** * Appender that tracks the events it receives, looking for a skipped * event. */ private static class CheckerAppender extends AppenderSkeleton { /** The next message we expect to receive. */ private long nextMessage = 1L; /** Store all the received messages in this list. */ private final List messages = new ArrayList(); public void close() { } public void append( final LoggingEvent event ) { // Do nothing if the error has already been found. // This prevents the output from being too yucky. if( errorFound ) return; try { // Save the new event messages.add( event.getMessage() ); // Extract the long from the event final long newMessage = Long.parseLong( (String)event.getMessage() ); // Look for a skipped event if( newMessage != nextMessage ) { // Error found, set the flag to shut things down errorFound = true; // Make a stink about it... System.out.println( "Message Skipped: got " + newMessage + ", but expecting " + nextMessage ); for( int i = 0; i < messages.size(); i++ ) { System.out.println( "messages(" + i + ") = " + messages.get( i ) ); } System.out.println( "--- done ---" ); // Okay, we can exit now donePrinting = true; } // Update the next expected message nextMessage += 1; } catch( final NumberFormatException e ) { System.err.println( "Couldn't parse message" ); System.exit( 1 ); } } public boolean requiresLayout() { return false; } } }
Created attachment 127 [details] Program that creates the described error (skipped events)
Aaron, The AsyncAppender is not supposed to be interrupted, so why are you trying to interrupt it? With you test program I get plenty of lines of the form: log4j:ERROR AsyncAppender cannot be interrupted. java.lang.InterruptedException at java.lang.Object.wait(Native Method) at java.lang.Object.wait(Object.java:420) at org.apache.log4j.AsyncAppender.append(AsyncAppender.java:110) at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251) at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders (AppenderAttachableImpl.java:57) at org.apache.log4j.Category.callAppenders(Category.java:253) at org.apache.log4j.Category.forcedLog(Category.java:443) at org.apache.log4j.Category.info(Category.java:691) at SkipEvent.main(SkipEvent.java:51) The AsyncAppender does not support thread interruption. What's wrong with that? What am I missing? Thanks, Ceki
My mistake. You are interrupting your own thread. That is your prerogative and log4j should support it. Ceki