Logging and Other Facilities of Last Resort
There are times when all reasonable seams fail your purpose. You beat your head against a wall. “How can I test this piece of code?” you scream in frustration. You want to test the code. You need to test the code. Your obsession with mastery over the system will not let you quit. Such moments lead to desperate decisions.
First, take a break. Get some fresh air. Go for a walk. Take a nap. Have a smoke, if that is your vice. Check your e-mail. Read a chapter of a good novel. Do whatever you have to do to break the fixation, distract your brain, and get some space. If after all of that you still need to beat the challenge, read on and consider the end of the test-seam rope, but see Figure 12-1.
I hope I have scared you enough to think carefully before using the techniques I am about to present. They are real. They are useful. Let’s start by discussing why they should be applied cautiously.
As we saw in Chapters 4 and 5, we want to verify intent over implementation, minimize coupling, prevent tests from interacting with each other, and avoid techniques that inhibit running tests reliably in parallel. The seams we are about to discuss violate all of these principles. Some facilities in our development frameworks exist for developer convenience. Others have broader applicability, but have much looser requirements for whether and where they are used in our code. Logging, monitoring, and sometimes security fall into these categories. While few will tell you to avoid logging, you will rarely be told where to place your logging statements, particularly the ones that only support debugging.
These facilities tend to be optional and implementational. They do not exist in the requirements. Their existence and placement are largely discretionary, deriving a high degree of implementation coupling from dependence on specific usage. At the same time, their role as a centrally configurable and available capability gives them a singleton nature that could allow mistaken test interaction in sequential or parallel execution.
Logging is the most common example of the kind of facility we are discussing. Listing 12-15 shows Java code using log4j.13 In this case, I added the debug statement exclusively for testing purposes to verify an intermediate computation. While most developers use the message parameter to the debug statement as a String, the interface only requires it to be an Object, so we can freely pass intermediate.
13. Note that the other Java logging frameworks like java.util.logging, sl4j, and logback all have similar functionality. Most modern logging frameworks in other languages follow suit.
Listing 12-15: Java code using log4j as an explicitly added debugging seam
public class SUT {
private static final Logger LOG =
Logger.getLogger(SUT.class);
public void testMe() {
// Bunch of code
...
Integer intermediate = computeSomething();
// Important: Keep this for testing purposes!
LOG.debug(intermediate);
// Continue with computation
...
}
}
So how can we use this as a seam? Most applications configure log4j through a Java properties file or through XML configuration. The log4j framework comes with a large number of useful appenders—the software components that add messages to the message stream—enough to satisfy most applications. Few applications need to write their own appenders or manipulate them programmatically. However, the log4j framework has a complete programmatic API with which it implements the configuration-based features most developers know and love.
Listing 12-16 shows how we can write a custom appender to capture the logged value and verify it after the code is exercised. Even in a simplified form, the example is a bit lengthy. We define the before and after methods to guarantee that we clean up the appender after every test. Otherwise, we would have to use a try/catch with finally. We also need to cache the appender so that we can remove it and the prior log level so that we can restore it. Once we do that, verification using the appender is as simple as retrieving the cached value.
Listing 12-16: Testing the code in Listing 12-15 using a custom logging appender
public class SUTTest {
private ResultCaptureAppender appender;
private Level oldLevel;
@Before
public void configureAppender() {
appender = new ResultCaptureAppender();
Logger log = Logger.getLogger(SUT.class);
log.addAppender(appender);
oldLevel = log.getLevel();
log.setLevel(Level.DEBUG);
}
@After
public void removeAppender() {
Logger log = Logger.getLogger(SUT.class);
log.removeAppender(appender);
log.setLevel(oldLevel);
}
@Test
public void testTestMe() {
Integer expectedIntermediate = 17;
SUT sut = new SUT();
sut.testMe();
assertEquals(expectedIntermediate,
(Integer) appender.getValue());
}
private class ResultCaptureAppender
extends AppenderSkeleton {
private Object value;
@Override
protected void append(LoggingEvent loggingEvent) {
value = loggingEvent.getMessage();
}
public Object getValue() {
return value;
}
}
}
However, the code makes some simplifying assumptions that are not very practical. For one, it assumes that our instrumentation is the last logging statement in the testMe() method. Another logging statement after the one shown would overwrite our cached intermediate value. We could compensate by storing all of the logged objects, even storing their call stacks. If this is a testing mechanism we want to reuse it may be worth it, but we need to recognize that we’re building complex testing-support infrastructure that may itself need tests to ensure continued correctness.
The implementation of the appender also chooses to leave issues of casting the type of the message to the caller. This makes the appender general purpose but clutters the tests themselves. Shifting the casting to the appender code runs the risk of throwing bad cast exceptions. We can avoid the exception by testing for types in the appender, but that also increases the complexity of our test instrumentation. Regardless of where the casting or type checking is done, we have coupled our test code to the internal data representation of the intermediate result.
Additional maintenance concerns suggest that we should avoid this technique. We dutifully commented the logging statement to help preserve its presence. How do we guarantee that future maintainers remove the comment if they come up with a better way to test the code? Earlier we discussed what would happen if another logging statement were added after the crucial one. No form of comment would provide a very apparent deterrent to that kind of change. The test failure would highlight it if we were lucky enough to have distinct data in the next log statement. Either way, it would require additional logic to hone in on exactly the logging usage we care about for the test, and additional tests using the technique would complicate things further.
Despite all of the fragility and shortcomings of the technique, there are times when it is the best way to test. Chapter 13 shows an example of using an appender to reproduce a threading race condition in a situation that was otherwise unreachable.