Bug 1505 - Incorrect use of wait() in AsyncAppender.append() can result in lost events
Incorrect use of wait() in AsyncAppender.append() can result in lost events
Status: RESOLVED FIXED
Product: Log4j
Classification: Unclassified
Component: Appender
1.1beta
PC All
: P1 normal
: ---
Assigned To: log4j-dev
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2001-04-25 08:46 UTC by Aaron Greenhouse
Modified: 2005-03-20 17:06 UTC (History)
0 users



Attachments
Program that creates the described error (skipped events) (4.08 KB, text/plain)
2001-04-25 10:46 UTC, Aaron Greenhouse
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Aaron Greenhouse 2001-04-25 08:46:34 UTC
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;
    }  
  }
}
Comment 1 Aaron Greenhouse 2001-04-25 10:46:21 UTC
Created attachment 127 [details]
Program that creates the described error (skipped events)
Comment 2 BugZilla Maintainer Account 2001-04-26 01:38:10 UTC
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
Comment 3 BugZilla Maintainer Account 2001-04-26 01:45:39 UTC
My mistake. You are interrupting your own thread. That is your prerogative and 
log4j should support it. Ceki