Example: Injecting Synchronization through Logging

Although I quite melodramatically warned against exploiting logging frameworks for testing, some race conditions require their use. Let’s look at a real-life example I encountered.

Consider the code in Listing 13-11. At first blush, it may appear that this code is thread-safe. Java guarantees that the individual operations of the Vector class are thread-safe. The retrieval of the first element and its removal are in a synchronized block. However, small though it may be, the time between the test for whether logRecords is empty in the while condition and the synchronized block in which that test is acted on represents a classic check-and-modify race condition. When this method in invoked in high volumes, the call to logRecords.firstElement() occasionally throws a NoSuchElementException, indicating that the container is empty.

Listing 13-11: An example of a race condition with a logging seam

Click here to view code image

private static final Logger =
  Logger.getLogger(AuditTrail.class);
private final Vector<AuditRecord> logRecords =
  new Vector<AuditRecord>();

public void postFlush(...) {
  ...
  while (!logRecords.isEmpty()) {
    log.debug("Processing log record");
    AuditRecord logRecord;
    synchronized (logRecords) {
      logRecord = logRecords.firstElement();
      logRecords.remove(logRecord);
    }
    // Process the record
    ...
  }
}

Fortunately, the original code author included a debugging statement in the loop. Listing 13-12 shows an Appender that we can use to exploit the seam. It simply waits, using itself as the monitor whenever a message is appended. If there were more than one log statement, or we wanted the lock to engage conditionally, we could create a more sophisticated implementation.

Listing 13-12: A log4j Appender implementation for thread-synchronization control

Click here to view code image

class SynchronizationAppender extends AppenderSkeleton {
  @Override
  protected void append(LoggingEvent loggingEvent) {
    try {
      this.wait();
    } catch (InterruptedException e) {
      return;
    }
  }
  ... // Other required overrides
}

Listing 13-13⁹ shows how the Appender from Listing 13-12 can be used to reproduce the race condition and eventually verify our fix. It runs the software under test on a separate thread after configuring log4j to use the custom Appender. After ensuring that the thread gets into the waiting state induced by the log statement, it removes the queued record and releases the thread. The thread was executed using a Callable, whose Future object is used to determine whether the NoSuchElementException is thrown. The exception indicates test failure.

9. This example was originally used in an article for InformIT magazine. The full code example can be found with the article at http://www.informit.com/articles/article.aspx?p=1882162.

Listing 13-13: Using the Appender from Listing 13-12 to force the race condition in Listing 13-11

Click here to view code image

@Test
public void testPostFlush_EmptyRace()
        throws InterruptedException, ExecutionException {
    // Set up software under test with one record
    AuditRace sut = new AuditRace();
    sut.addRecord();
    // Set up the thread in which to induce the race
    Callable<Void> raceInducer = new PostFlushCallable(sut);
    FutureTask<Void> raceTask =
      new FutureTask<Void>(raceInducer);
    Thread inducerThread = new Thread(raceTask);
    // Configure log4j for injection
    SynchronizationAppender lock =
      new SynchronizationAppender();
    Logger log = Logger.getLogger(AuditRace.class);
    log.addAppender(lock);
    log.setLevel(Level.DEBUG);

    inducerThread.start();
    while (Thread.State.WAITING != inducerThread.getState());
    // We don't want this failure
    // to look like the race failure
    try {
        sut.getLogRecords().remove(0);
    } catch (NoSuchElementException nsee) {
        Assert.fail();
    }
    synchronized (lock) {
        lock.notifyAll();
    }

    raceTask.get();
}

I will repeat that this technique requires some caution. The same reasons that programmers typically overlook logging statements as testing seams can also contribute to fragile tests, particularly when forcing race conditions. Casually removing the logging statement used as a seam can lead to unusual test failures. The try/catch around the removal of the queued record attempts to capture the possibility, but it could still require some careful diagnosis. Similarly, the addition of extra logging statements, in combination with the simple implementation of the SynchronizationAppender, could cause the test to hang indefinitely and possibly fail due to timeouts. Conditionally waiting based on the first execution or on the content of the message being logged could address those concerns.

The other important step omitted in this example is the removal of the shared Appender. The power of logging frameworks like log4j derives from a central singleton nature that coordinates the logging activity and configuration. The unique instance is a shared resource across all tests, which can cause appender changes to apply to other tests. A more robust implementation would preserve the existing appender structure and restore it at the end of the test.