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.
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.
class SynchronizationAppender extends AppenderSkeleton {
@Override
protected void append(LoggingEvent loggingEvent) {
try {
this.wait();
} catch (InterruptedException e) {
return;
}
}
... // Other required overrides
}
Listing 13-139 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.
@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.
18.216.27.251