Reproducing Race Conditions in Tests
Stephen Vance is the author of the book Quality Code: Software Testing Principles, Practices, and Patterns (April 2013).
Like this article? We recommend
Like this article? We recommend
Like this article? We recommend
Product teams increasingly rely on automated tests to support the quality of their software. Test-driven development creates the tests as an integral part of the development process. Acceptance test–driven development and behavior-driven development create tests as executable specifications for the software. Contemporary software development methods create a lot of tests.
All these tests, if written well, justifiably give us a higher level of confidence in the correctness of our software. We could even naively or arrogantly start to think that we can produce bug-free software. But a variety of factors—increasing complexity, incomplete or ambiguous specifications, reliance on third-party software, and distributed and asynchronous systems, to name just a few—keep us humble.
Race conditions are among the most insidious of these issues. While programming paradigms are shifting to help us write safe concurrent code, the technology options in this area are young and numerous. If you have to work on an existing system or in a particular technology context, you probably deal with traditional approaches to concurrency, involving threads and locks.
Many groups striving to produce high-quality software have policies stating that bugs must be reproduced in tests, to help ensure that those bugs don't recur. Sometimes a single bug results in multiple tests. Reproducing the bug at a system level or integration level may result in one test. If you subscribe to the philosophy that every bug can be reduced to one or more bugs at the unit level, then you'll also require unit tests to reproduce the localized defect. But what can you do if the defect is a race condition? This article examines the anatomy of race conditions, laying out an approach to understanding the race condition and then exploiting that understanding to reproduce the race condition deterministically in tests.
Anatomy of a Race Condition
Much has been written about race conditions over the years, so I'll just provide a very quick overview here, enough to move us forward. A quick Internet search or perusal through computer science texts on algorithms, operating systems, or many common programming languages will easily provide additional depth.
A race condition occurs when two or more threads of execution modify the same data simultaneously. This simultaneity may be truly concurrent execution on separate cores, or simply the effectively concurrent form caused by time-sliced execution on the same core.
The data modification most typically involves a read and a write where locks are not used to prevent the data from changing between the read and the write. The data can be as simple as a single variable or as complex as a collection of objects that need to be kept mutually consistent. Operations that preserve the required consistency are called atomic.
One of the simplest examples of a race condition is the unprotected statement
i = i + 1
where i is shared data. Let's assume for this discussion that compilation translates this statement to executable code in a literal way:
- Thread A reads the value of i into a register and increments it.
- Thread B does the same thing into its own register.
- Thread A copies the value from the register back to storage for i.
- Thread B copies its register value.
If the initial value of i was 17, both threads read the value 17 into their respective registers. Both threads increment 17 to 18. Both threads copy the value 18 back to the variable storage. The result of two threads increasing the value of i by 1 should be a net increase of 2, but it's actually 1. But this happens only if two threads try it at the same time, so it may occur in a very small percentage of executions. This kind of sporadic behavior is characteristic of race conditions.
The span of time or code during which the data needs to be consistent is known as the critical section. The critical section interests us for two reasons:
- The critical section contains the bug.
- The critical section contains our opportunities to reproduce the bug.
In the previous simple example, the critical section is small and subtle. It occurs completely within the single statement. The read operation is the use of the variable i on the right side of the expression. The write operation is the assignment of i on the left side of the assignment.
The compactness of this critical section and the fundamental nature of the participating data and operations makes this particular race condition difficult and fragile—but not impossible!—to reproduce in tests. Depending on the target architecture, it could be fixed simply by turning on compiler optimizations, changing the expression to i++ or i+=1, or using system concurrency primitives such as Java's AtomicInteger. Fortunately, in my experience, most race conditions involve higher-level constructs where the responsible read and write are farther apart.
Understanding How Race Conditions Occur
A high-yield way to find race conditions by visual inspection involves looking at where shared data is read and written and then determining whether it's contained in the same locking scope. Let's apply that rule to a real-world race condition from a recent production anomaly I diagnosed. Here's an excerpt from the Java code of the AuditTrail class:
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
...
}
}
I took out some error handling and some other code irrelevant to the race condition, but the race condition itself is presented verbatim. This code was written in a literate manner that reveals its intent. The code is entirely within the contents of a class of which there is only a single instance. Two other methods for our purposes stand in for the full functionality of the class: addRecord() adds an AuditRecord to logRecords, and getLogRecords() has restricted access for testing purposes.
Do you see the race condition? At what places is logRecords read? In this case there are two reads: One triggered the exception and the other checks whether the Vector is empty. Where is logRecords changed? In this code, the remove() call is the only write to logRecords.
The original code author recognized the potential for a race condition, as evidenced by the synchronization block around the record removal. The use of synchronized declares a recognition of a critical section and defines the recognized boundaries. Unfortunately, one of our reads is outside of this critical section, which creates our race condition.
The NoSuchElementException tells us that even though we got into the while loop, which only occurs if logRecords contained elements, there were no elements by the time we tried to retrieve the first element. Even without fully understanding the sequence of events, the removal of an element is consistent with the symptom. Here's how the race condition transpires:
- Thread A sees that logRecords is not empty, with only one record remaining, and enters the loop.
- Thread B also sees that logRecords is not empty and enters the loop.
- Thread A enters the synchronized block, preventing Thread B from entering the block, and retrieves and removes the first element from logRecords.
- Thread A leaves the synchronized block, freeing Thread B to enter it.
- Thread B enters the synchronized block and attempts to retrieve the first element from logRecords, but finds it empty, triggering the NoSuchElementException.
Spotting race conditions like this takes some practice. By identifying your read and write operations and narrowing your write operations to those that are consistent with the symptoms, you can simplify the process. As you practice finding race conditions, they'll become more apparent to you.
We have now hypothesized our critical section as extending from the empty check in the while condition to after the remove() call in the synchronized block. How can we prove it? How can we reproduce the race condition so as to reasonably verify that our hypothesis is correct?
Reproducing Race Conditions
In Working Effectively with Legacy Code, author Michael Feathers introduces the concept of a seam as "a place where you can alter behavior in your program without editing in that place." To reproduce race conditions, you need to find a way to get two threads into your critical section, both doing the read operation that starts the race, and then stopping them before they reach the write operation. You want to find a seam that will let you synchronize two threads.
A synchronization seam can take many forms. Any method call or other behavior you can override or intercept makes a good seam. Code already written to be concurrent has an additional type of seam that's perfect for our purposes—the existing synchronization. We want to exploit the existing synchronization for our example, but the isEmpty() method is synchronized on the same lock, making it difficult to stop execution between that and the synchronized block. Instead, we'll use the seemingly innocuous debug logging statement as our seam.
Modern logging frameworks in Java, like the log4j used here, can be dynamically reconfigured to change output targets, logging levels, and so on. The features that allow reconfiguration for logging purposes also allow us to inject handlers for synchronization purposes. In log4j, a message handler is known as an appender. You can add appenders programmatically at any scope you want. The appender we'll use to exploit the seam is as follows:
class SynchronizationAppender extends AppenderSkeleton {
@Override
protected void append(LoggingEvent loggingEvent) {
try {
this.wait();
} catch (InterruptedException e) {
return;
}
}
... // Other required overrides
}
We also create a java.util.concurrent.Callable for launching the call to postFlush() on a thread. We use a Callable with a FutureTask to let us determine whether any exceptions were thrown.
Following is the code for the test method:
@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();
}
After we set up the software under test and the thread to invoke it, we reconfigure the logging.
Once we've set up the fixtures, we start the thread and wait for it to get to its waiting state. Note that the use of Thread.State.WAITING or Thread.State.BLOCKING depends on the mechanism you use to synchronize. We constructed the test to make the thread wait after the check for whether logRecords is empty, so we remove the single existing record and let the thread run.
If the race condition exists, the call to raceTask.get() will throw an ExecutionException with a NoSuchElementException as its cause, proving the existence of the race condition. Fixing the race will make the test pass.
A fix for this race is worth mentioning because it helps to illustrate another important point. Reproducing race conditions is a clear example of white-box testing. We need to be very careful to test to the intent where we can, but thread synchronization is very much about implementation. A test that reproduces a race condition may well need to be rewritten, depending on the nature of the fix. It's worth asking yourself how you might fix the race to narrow your options for creating the test, so that you can avoid the choices that would cause your test to become invalid.
A simple fix for this race is to check again whether logRecords is empty in the synchronized block; if it is, break out of the loop. This approach leaves a read outside of the critical section to control the loop, but compensates by reiterating the check within the critical section. A more substantial restructuring that ensured the reads and writes were all in the critical section together would most likely break the test we wrote.
Conclusion
Deterministic reproduction of race conditions is possible. Those techniques require a bit of intuition and a solid understanding of the synchronization mechanisms at your disposal, but the benefits to ensure that race conditions remain fixed can justify the investment.