Archive for August 13th, 2007

Fun with EasyMock

Monday, August 13th, 2007

I’m a big fan of Test-driven development and have been using JUnit for 6 or 7 years (since around v3.4 or v3.5). I’ve written lots of mock objects (from simplistic dummy concrete classes that implement an entire interface, to Proxy-based mocks, to a pretty decent mock JMS library) and played with various mock libraries, but the one I’m sticking with and using almost exclusively is EasyMock.

Reinventing a wheel is great for learning, and I’ve done it a lot. But perhaps in a sign that I’m getting older, I’m more concerned with getting stuff done, so now I tend to lean towards existing solutions when good ones exist. I searched for what people tend to use for mock objects and jMock and EasyMock are popular. I prefer the method-based approach of EasyMock to the string-based approach of jMock, since code changes will cause the tests to break immediately, and the mocks will be refactored along with the rest of the code if I use the IDE’s refactoring features.

The general pattern with creating mocks for a tier of your application is that you’re trusting that that tier is tested and works correctly, so it’s appropriate to have mocks return hard-coded values. We’re testing that the caller of the mocked interface does the right thing with correct (or incorrect) inputs, so mocks help us to focus on what’s being tested in isolation.

I’d always found it difficult to unit test Spring MVC controllers, since it seems like they need a running container, and I don’t want to deal with the hassle of setting up Cactus. Plus it seems somewhat useless to test controllers, since they shouldn’t be doing much that isn’t tested in proper automated functional tests. If they do too much business logic, they should be refactored to push that work out to the services layer, right?

The reality is that we do too much business logic in controllers, and usually it’s lazyness but often it’s being pragmatic. We also tend to often do even more “illegal” activities in controllers, such as writing directly to the response rather than delegating to a View. This is usually the case for XML and JSON generated for Ajax responses. So until these get refactored, they need to be tested.

It’s helpful to have partially-functioning servlet container classes such as HttpServletRequest and HttpServletResponse, and the Spring Mock library (spring-mock.jar) is great for that. But for creating mocks for DAOs, services, and other interface-based dependency-injected resources, EasyMock greatly simplifies things. And with their user-contributed Class Extension, you can even mock out concrete classes.

The syntax takes a while to get used to. Basically the flow that I tend to use is:

  1. Create a mock
  2. call expect(mock.[method call]).andReturn([result]) for each expected call
  3. call mock.[method call], then EasyMock.expectLastCall() for each expected void call
  4. call replay(mock) to switch from “record” mode to “playback” mode
  5. inject the mock as needed
  6. call the test method
  7. call verify(mock) to assure that all expected calls happened

As simple as that may sound, it can look very weird at first. Say I have an interface:

public interface Thing {
   void doSomething(String parameter);
   int doSomethingElse(String parameter, int otherParameter);
}

I can create a mock for it via:

Thing thing = EasyMock.createMock(Thing.class);

Then I can register expected calls via

EasyMock.expect(thing.doSomethingElse("woot", 5)).andReturn(123);
EasyMock.expect(thing.doSomethingElse("fubar", 45)).andReturn(321);

thing.doSomething("p");
EasyMock.expectLastCall();

This says that in my calling code, when the client calls thing.doSomethingElse("woot", 5) to return 123, when the client calls thing.doSomethingElse("fubar", 45) to return 321, and to expect a call to thing.doSomething("p").

I can then inject this mock into the class being tested in place of the real one, trusting that it will return known results. I can then concentrate on assuring that the tested class does the right thing.

Thanks to EasyMock, my productivity for testing services and controllers is way up – and my code coverage percentages are too.

WTF is Log4j’s FQCN?

Monday, August 13th, 2007

I’ve browsed through the Log4j source code several times when I needed to write a custom appender, debug some obscure logging issues, etc., and I’d seen the variables FQCN and callerFQCN but never really needed to know what those were until this week.

I had gotten frustrated with this bloated (but necessary) pattern in a lot of our code:

if (log.isDebugEnabled()) {
   log.debug("foo=" + foo + ", bar=" + bar);
}

The isDebugEnabled() check is necessary since foo and bar might have large and/or expensive toString() realizations, and if the Debug level isn’t enabled, the string concatenation will have been wasted, a potentially significant performance problem.

So we do a lightweight check to see if it’s even necessary to build up the string; the unfortunate part is that it takes 3 lines instead of 1, and if there’s a lot of debug logging in a class a significant portion of the code is just logging.

To simply things I borrowed an idea from Seam‘s logging and wrote a utility class that accepts a logger, a message with {0}, {1}, etc. placeholders in MessageFormat style, and varargs parameters to replace the {0}, {1} placeholders, e.g.

Logger.debug(log, "foo={0}, bar={1}", foo, bar);

and the Logger class handles the test that the provided log has debug enabled, and uses MessageFormat to build the final message only if necessary.

This worked great and I switched over a lot of verbose logging calls to use the new approach. But a team member complained that he’d turned on class (%C) and method (%M) logging, and it was claiming that the entries were being logged from the utility class Logger and method debug (although the category name was of course correct). I hadn’t noticed this since he’d only turned on these expensive extra options to debug some obnoxious bugs currently wreaking havoc on our application.

We’re using Commons Logging1 so I needed to cast the Log instance to a Log4JLogger to access the native Logger via getLogger().

Once I do that, I can convert

log.debug(message);

to the equivalent but more useful

((Log4JLogger)log).getLogger().log(Level.DEBUG, message);

or more specifically

((Log4JLogger)log).getLogger().log(FQCN, Level.DEBUG, message, null);

where the last parameter is the optional Throwable, not relevant to this discussion.

But what’s the FQCN? This is a String, “org.apache.log4j.Logger” if you’re using Log4j directly. The purpose of this is to be able to find the calling method if necessary. Log4j uses a stack trace from a new Throwable to determine the caller (hence the expense of these logging parameters – they shouldn’t be used except for unusual cases).

A stack trace generated in Log4j’s code will have some number of stack elements from the Log4j method calls, then the logger call itself, then the application stack elements. So if you know the fully qualified class name of the logger class, then you can find it in the stack trace, go one deeper, and you know the class name, method, and line number (if javac debug is on).

But I’d introduced one more stack element into the trace, defeating the lookup. Luckily for me, all I needed to do was the replacement above, and substitute the full class name of my utility class and the actual calling method is now correctly resolved.

  1. One of the first things I wanted to change when I started on the project was to remove Commons Logging and use Log4J directly since it provides no benefit in our application. I should have seen the nonsensical knee-jerk refusal to consider this as an omen of things to come, but I didn’t. Oh well, more on that later 😉 [back]

Creative Commons License
This work is licensed under a Creative Commons Attribution 3.0 License.