BT

Using Logging Seams for Legacy Code Unit Testing

Posted by Ian Roughley on Aug 01, 2006 |

Working with legacy code can be difficult at the best of times. But when it comes to adding new features, refactoring or maintaining code that you are not familiar with, it can become overwhelming. It can be especially difficult if you have been working with agile techniques for a few years and suddenly you are faced with copious amounts of code and no test case for as far as the eye can see.

So what can be done? The simple answer is to create unit tests. But, as you start modifying the code to break dependencies and enable testability, this can lead you into more trouble. What you really need is an unobtrusive way to evaluate expressions, find values, and determine which branch of the code is currently executing.

In his book "Working Effectively with Legacy Code," Michael Feathers talks about finding seams in legacy code to facilitate testing. The definition he provides for a seam is "a place where you can alter behavior in your program without editing in that place." Types of seams vary among languages, and for Java he defines two categories that are relevant, "link seams" - whereby ordering the class path differently, different classes can be substituted for testing; and "object seams" - where calls to constructors or methods are made using a sub-class or mock implementation, rather than the originally expected class. ( For more information see chapter 4 of "Working Effectively with Legacy Code", by Michael Feathers).

Another seam that I have found to be advantageous is the logging seam. Using this seam you can easily create unobtrusive unit tests around classes, without needing to edit class logic as well as avoiding behavior changes.

Finding the Seam

The untested code scenario from above is fairly common when working with legacy code or code that was not written with testability in mind. Examples are large methods and classes, complex branching (usually many levels of branching in the same method) and objects that are instantiated directly in the code when they are needed. Under these circumstances (as well as other others) the usual testing toolkit doesn't work well. The one advantage is that most code utilizes a logging framework.

From a testing perspective, it doesn't really matter what the original purpose of the logging code was. Whether it was used for information, debugging, or tracing - the important thing is that it provides telemetry information. This telemetry information can then be repurposed and used within unit tests, providing the safety net needed to confidently refactor code and add new features.

Additionally, adding new logging code into existing code is benign - it will not affect the existing functionality or behavior. This means that we can beef-up logging with new statements to report information (such as expression results, object instance values, and branching information) that we want to verify via unit tests. More details on this step will be provided later in the article.

The Test Case

In true testing fashion, let's develop the unit test first.

But before we get started, let's assume that the legacy code we are working with has been written in Java, and also that it utilizes the log4j logging framework from the Apache foundation.

The structure of the test case should follow the mock testing paradigm. These steps are:

  1. Create a mock object for the object being used by the class to be tested, hereafter called "ClassUnderTest".
  2. Configure the mock object with the testing expectations
  3. Apply or inject the mock object into the class under test
  4. Run the method being tested
  5. Validate that the expectations were met

In our case we are substituting the mock object for a logging appender. The appender will work (function) the same as a mock object - it will be primed with expectations before the test is run; it will capture calls from the class during testing; and finally, it will report on whether the expectations were met and whether any additional calls were made.

Here's the structure of the test case in code:

	// create the testing appender
TestLoggingAppender appender = new TestLoggingAppender();

// add expectations
appender.addMessageToVerify("count=3");
appender.addMessageToVerify("finished processing");

// add the appender to those associated with the class under test
Logger log = LogManager.getLogger(ClassUnderTest.class);
log.setLevel(Level.INFO);
log.addAppender(appender);

// do usual test setup and configure the class under test
ClassUnderTest testme = new ClassUnderTest();
...

// run the method under test and verify the results
testme.myMethod();

// ensure all the expectations are met
assertTrue( appender.verify() );

The only trick here is to remember that when you use log4j, there are many different logging levels. When you configure the appender to receive logging information, you need to ensure the logging level is correctly set. In the code above, "log.setLevel(Level.INFO)" performs this function.

The Test Logging Appender

Finally, it's time to develop the test logging appender. We already know the methods that the test case is calling on the appender, so this gives us the initial structure of the class. These methods are "addMessageToVerify" and "verify."

Here is the first method.

	public void addMessageToVerify( String msg  ) {
            called.put( msg, new State( msg, true, false ) );
        }

When called, a new entry is added to a list of messages that is being managed by the appender. As well as the message, which is being used as the key for easier lookup, a state object is stored. The state object is a simple object that stores the message and two flags - denoting whether the message should be expected and whether it was called.

Next is "verify". This method uses the internal list of messages that has already been created. Returning a value of "true" signifies that all the messages that were expected to be called actually were, and that there were no additional messages logged to the appender. Otherwise a "false" value will be returned. Here's what it looks like:

	public boolean verify() {
boolean result = true;
for( Iterator i=called.keySet().iterator(); i.hasNext(); ) {
State state = (State)called.get(i.next());
if( (!state.shouldCall() && state.wasCalled()) ||
(state.shouldCall() && !state.wasCalled()) )
result = false;
}
return result;
}

We have been talking about messages that are coming from the logging framework, but how does this happen? In order for our test logging appender class to accept logging messages, two things need to happen.

The first is that our test logging appender needs to be enabled in the test case. Logging is enabled with the code "LogManager.getLogger(ClassUnderTest.class)", and then our test logging appender is added to the list of appenders to receive logging messages with the call "log.addAppender(appender)."

Second, our test logging appender needs to extend the ConsoleAppender class. This introduces a new method, doAppend(LoggingEvent event), that we now need to implement:

	public synchronized void doAppend(LoggingEvent loggingEvent) {
String msg = loggingEvent.getMessage().toString();
if( called.containsKey(msg) )
((State)called.get(msg)).setCalled(true);
else
called.put( msg, new State( msg, false, true ) );
}

Similar to the addMessageToVerify method, the doAppend method manipulates the internal list of messages. If the messages being logged exits, the doAppend method updates the status flag to denote that it has been called. If the message does not exist, then a new entry is added to the list with the flags set to denote that the message was not expected but called.

This completes the implementation of the test logging appender class. The complete implementation can be seen in listing 1.

Exploiting the Seam

The final step is to add the logging statements to the ClassUnderTest.

In our test case above we had the following two lines of code, which verifies that something happened three times, and that processing finished (presumably without exceptions).

	appender.addMessageToVerify("count=3");
appender.addMessageToVerify("finished processing");

A possible method that the above expectations test is:

	public void myMethod() {

// lots of code before the section we are interested in

try {
FileReader file = new FileReader("transactions.log");
BufferedReader reader = new BufferedReader(file);

String data;
int count = 0;
while( (data = reader.readLine())!=null ) {
process(data,count++);
}

LOG.info("count="+count);
LOG.info("finished processing");
} catch( Exception e ) {
// error processing
}

// more code afterwards
}

This is a simple example, and not indicative of what would normally be found in legacy code. The important thing to remember is that in order to test this section of code within the method, only two logging statements need to be added. No functionality is modified, and no refactoring needs to be performed.

When thinking about what to log, the following guidelines can be used:

  • Static text can be logged to show starting and ending boundaries for the test area
  • Static text can be logged within branches or loops to determine location
  • Loop counter values can be logged to determine which loop iteration is being executed
  • Branch determination logic (that which determines whether you do the "if" or the "else") can be logged
  • Any variable (class, method or block scoped) value can be logged
  • Any expression can be evaluated and the result logged

Conclusion

With the help of a logging framework, creating unit tests for legacy code can be an easy task. You can utilize existing logging, and unobtrusively add new logging statements to evaluate expressions, find values, and determine which branch of the code is currently executing. Now, with the test logging appender in your toolkit, you can confidently refactor existing legacy code and add new features without the fear of breaking existing functionality.

Listing 1 - The complete TestLoggingAppender listing.

public class TestLoggingAppender extends ConsoleAppender {

private Map called = new HashMap();

public boolean verify() {
boolean result = true;
for( Iterator i=called.keySet().iterator(); i.hasNext(); ) {
State state = (State)called.get(i.next());
if( (!state.shouldCall() && state.wasCalled()) ||
(state.shouldCall() && !state.wasCalled()) )
result = false;
}
return result;
}

public void printResults() {
for( Iterator i=called.keySet().iterator(); i.hasNext(); ) {
State state = (State)called.get(i.next());
StringBuffer sb = new StringBuffer();
sb.append("Logging message '").append(state.getMsg()).append("' ");
sb.append("was ").append( state.shouldCall()?"expected ":"not expected ");
sb.append( state.wasCalled()?"and called":"and was not called");
System.out.println(sb.toString());
}
}

public void addMessageToVerify( String msg ) {
called.put( msg, new State( msg, true, false ) );
}

public synchronized void doAppend(LoggingEvent loggingEvent) {
String msg = loggingEvent.getMessage().toString();
if( called.containsKey(msg) )
((State)called.get(msg)).setCalled(true);
else
called.put( msg, new State( msg, false, true ) );
}

class State {

private String msg;
private boolean shouldCall;
private boolean called;

public State( String msg, boolean shouldCall, boolean wasCalled ) {
this.msg = msg;
this.shouldCall = shouldCall;
this.called = wasCalled;
}

public String getMsg() {
return msg;
}

public boolean shouldCall() {
return shouldCall;
}

public boolean wasCalled() {
return called;
}

public void setCalled(boolean called) {
this.called = called;
}
}
}

About the author

Ian Roughley is a speaker, writer and independent consultant based out of Boston, MA. For over 10years he has been providing architecture, development, process improvement and mentoring services to clients ranging in size from fortune 10 companies to start-ups. Focused on a pragmatic and results-based approach, he is a proponent for open source, as well as process and quality improvements through agile development techniques.

Hello stranger!

You need to Register an InfoQ account or to post comments. But there's so much more behind being registered.

Get the most out of the InfoQ experience.

Tell us what you think

Allowed html: a,b,br,blockquote,i,li,pre,u,ul,p

Email me replies to any of my messages in this thread

Are they really "unit tests"? by Eric Torreborre

Hi Ian,

Having worked today on both legacy code and logging (and a nasty bug,...), I like your idea a lot!

I can see 2 use cases for this technique: refactoring and bug-fixing. The first use case is the one you indicate: setting a safety net prior to refactoring.

Refactoring

My question is: "how do you know it's enough?". How many probes should be set in the code to be confident with refactoring? I feel that instrumenting one class alone cannot make you confident enough to refactor it? Did you have to instrument a lot of classes around the one you wanted to refactor before actually doing it? Was the result satisfactory?

The second use case is bug fixing.

Bug fixing

This can be a nice alternative to "not doing anything", when you encounter a bug. You fix it, you need to create a test for it and you may not have time to break dependencies to write a unit test for it (or you can't take the risk) [I have posted a blog entry regarding opportunities to refactor legacy code in a agile process and will update it to include your wonderful idea (etorreborre.blogspot.com)]

How to name those tests?

In any case, I think those tests would better be considered as "integration tests" and can serve as non-regression tests, but I won't call them "unit tests", since they indeed don't remove the dependencies the class under test relies on.

I am especially sensitive to the question of "integration tests" since they are often slow and fragile. I tend to prefer a mix of the followings tests: acceptance, unit, smoke and exploratory. Those 4 testing approaches looks like they are the most cost effective way of testing our application.


Thanks for your fine article,

Eric.

Why? by Srivaths Sankaran

There are couple of prefacing statements that are the basis for this technique:
But, as you start modifying the code to break dependencies and enable testability, this can lead you into more trouble

and
Examples are large methods and classes, complex branching (...) and objects that are instantiated directly in the code when they are needed. Under these circumstances (...) the usual testing toolkit doesn't work well.

I question this basic premise. Why won't the "usual testing toolkit" work? I don't see why one needs to "open" the code under test simply in order to test it. The one instance I can see this technique being of value is when the code under test is highly coupled.

Re: Are they really "unit tests"? by Ian Roughley

You're right, both these use cases are valid.

What I do is refactor the code using a logging seam. Once I know the refactoring is sucessfull, and nothing is broken, I use more common junit or mock object testing techniques to test the code to fix the defect.


My question is: "how do you know it's enough?". How many probes should be set in the code to be confident with refactoring? I feel that instrumenting one class alone cannot make you confident enough to refactor it? Did you have to instrument a lot of classes around the one you wanted to refactor before actually doing it? Was the result satisfactory?

I find when I use this technique, the code is usually in one large method of one class. I do as much instrumenting as necessary to feel confident that the changes I make are working correctly - sometimes this is 2 or 3 logging statements, sometimes is 20.

I was conflicted on whether to call these unit or integration tests. As I mentioned above, usually it's one large method that I am working within, so unit tests make more sense. Perhaps if I used the technique across multiple classes I would have called it integration testing.

Allowed html: a,b,br,blockquote,i,li,pre,u,ul,p

Email me replies to any of my messages in this thread

Allowed html: a,b,br,blockquote,i,li,pre,u,ul,p

Email me replies to any of my messages in this thread

3 Discuss

Educational Content

General Feedback
Bugs
Advertising
Editorial
InfoQ.com and all content copyright © 2006-2013 C4Media Inc. InfoQ.com hosted at Contegix, the best ISP we've ever worked with.
Privacy policy
BT