| testing.com > Testing Craft > Techniques (Developer Testing) > Testing a Trace.Java Bugfix |
Testing
Craft: Where
Software Testers Share Techniques |
I maintain a tracing package called Trace.java. This is the story of how I redid a small part of its code to fix a bug. This story shows how I create tests before I write code. It also explains how I do test design.
The story is a bit simplified. (There's one aspect of the problem I don't talk about, plus a couple of unmentioned details.) Other than that, it's true.
If anything in this account is unclear, please drop me a line: marick@testing.com.
The problem
Exploration
Planning the testing
Test design
Implementing the code
Despair
Post-coding cleanup
What bugs did I miss?
Trace.java is a package used by Java programmers, testers, server administrators and others to understand what happened during the execution of a program. It requires programmers to add tracing statements like the following to the code.
commTrace.eventm("PROBE message detected from IP address" + addr);
Messages like the following end up in a log. There is flexible control over which types of messages end up where.
=== 1997/09/22 13:52:09.342 (Incoming.parcel:Incoming.java:126) EVN
comm: PROBE message detected from IP address 123.44.53.12
The first line says that the eventm
message was "posted" in routine Incoming.parcel.
Specifically, it can be found at line 126 of file "Incoming.java".
How does Trace.java know that location information? In C, some of the information is available at compile time through the C preprocessor's __LINE__ and __FILE__ directives. In Java, it must be recovered at runtime. The way you do that is a little tricky. I have to explain the trick before I can explain the bug.
Trace.java contains a class called TraceMessage.
The TraceMessage constructor contains this code:
exception = new Exception();
Rather than throwing that exception, TraceMessage
hangs onto it. Why? Because inside that exception is a
representation of the Java runtime stack. That can be printed
into a String, which would look like this:
java.lang.Exception
at com.visibleworkings.trace.TraceMessage.<init>(TraceMessage.java:88)
at com.visibleworkings.trace.Trace.recordTraceMessage(Trace.java:348)
at com.visibleworkings.trace.Trace.worldm(Trace.java:482)
at Incoming.parcel(Incoming.java:126)
at Dump.main(Dump.java:34)
Note the highlighted line. It contains the
information we need. So all we have to do is "walk the stack"
three frames past the constructor frame (TraceMessage.<init>)
and parse it out.
The format of exception stack dumps is unspecified, so different VM providers are free to change them at will. They all seem to use one line per frame. Some of them have different formats for the information in a line, but it's not too hard for Trace.java to keep up with new VMs.
One day I was using Trace and I noticed it printed the wrong location information. It said the message came from the caller of the routine that actually posted it.
When I looked at the stack dump Trace was using, I saw that it looked like this:
java.lang.Exception
at com.visibleworkings.trace.Trace.recordTraceMessage(Trace.java:348)
at com.visibleworkings.trace.Trace.worldm(Trace.java:482)
at Incoming.parcel(Incoming.java:126)
at Dump.main(Dump.java:34)
Where's the call to the constructor? (It should be after "java.lang.Exception".) Apparently the on-the-fly compiler messed up the stack. That's a bug in the compiler, but Trace should be robust to bugs in compilers. The needed information is still accessible, so Trace should access it.
Before fixing the bug, I decided to see if there were any other compiler oddities to be robust against. I wrote some code that caused on-the-fly compilation. I quickly discovered another oddity:
java.lang.Exception
at com.visibleworkings.trace.Trace.recordTraceMessage(Trace.java:348)
at com.visibleworkings.trace.Trace.recordTraceMessage(Trace.java:348)
at com.visibleworkings.trace.Trace.worldm(Trace.java:482)
at Incoming.parcel(Incoming.java:126)
at Dump.main(Dump.java:34)
The compiler is misnaming the most recent frame on the stack.
It's actually the TraceMessage constructor, but it's
mislabeled as recordTraceMessage.
It's good that I noticed this. I'd been thinking of a fix that
searches for recordTraceMessage, then hops over its
caller's frame to find the frame that posted the message. That
wouldn't work, given this stack dump.
In my exploration, I was also reminded that Trace.java uses tracing itself. Here's one instance:
java.lang.Exception
at com.visibleworkings.trace.TraceMessage.<init>(TraceMessage.java:88)
at com.visibleworkings.trace.Trace.recordTraceMessage(Trace.java:348)
at com.visibleworkings.trace.Trace.worldm(Trace.java:479)
at com.visibleworkings.trace.TraceLog.shutdownAndSwap(TraceLog.java:587)
at com.visibleworkings.trace.TraceLog.handleFullLog(TraceLog.java:416)
at com.visibleworkings.trace.TraceLog.acceptBypassingQueue(TraceLog.java, Compiled Code)
at com.visibleworkings.trace.TraceLog.accept(TraceLog.java, Compiled Code)
at com.visibleworkings.trace.TraceSubsystemMediator.accept(TraceSubsystemMediator.java, Compiled Code)
at com.visibleworkings.trace.Trace.recordTraceMessage(Trace.java:353)
at com.visibleworkings.trace.Trace.worldm(Trace.java:482)
at Dump.main(Dump.java, Compiled Code)
How does this happen? Trace can be initialized to use fixed-size log files. When the logfile fills up, the next Trace message posted causes a new logfile to be opened. The code in Trace that does that will itself post trace messages. When I first wrote the code, that was useful in debugging.
So that's another special case to be aware of. It makes
impossible another fix: that of searching backwards through the
stack for recordTraceMessage. (I could take out the
trace messages from Trace.java, but that would be dangerous -
someone else changing the trace code would naturally put some
back in. That person should not have to contend with mysterious
failures.)
At this point, I'd developed a rough sketch of the fix. I
couldn't count stack frames from the beginning of the stack dump.
I'd have to search for the right recordTraceMessage
and count from it, keeping special cases in mind. But the next
step isn't to work on the code; it's to write tests.
How to test? I use Beck and Gamma's JUnit test framework. It's a
simple and capable one. Your tests are methods with names like TestTraceCaller.
The methods call the code under test. Then they use an assert
method to check whether the actual results match the results you
expected. If not, the test fails.
In order to write a test, then, you need to know the interface. Here's the one I chose:
TraceCaller.TraceCaller(Exception).
methodName, fileName,
and lineNumber. If there was a problem
parsing the stack dump, information that couldn't be
found would be labelled "method?", "file?",
or "line?"This is almost, but not quite, the same as the previous version's interface. That version took a "count" argument in the constructor. That was the number of frames to skip to find the frame that posted the call. (For reasons not important to this story, it wasn't always 3.)
For testing purposes, there's a problem with this interface.
The whole point of this exercise is to make TraceCaller
cope with oddly broken stack frames. How would a test generate a
broken exception to pass to the constructor?
I decided it shouldn't. There would be a second constructor, TraceCaller(String),
which takes a string, supposedly from an Exception's stackdump,
and parses that. My tests would test that constructor, not
the constructor the rest of the Trace code really uses.
That's a safe thing to do because I know that all that TraceCaller(Exception)
is going to do is print the Exception into a string, then call
the same parsing code as TraceCaller(String). My TraceCaller
tests won't be exercising the exception-printing code, but:
I'm belaboring all this because it lets me call attention to two points important to programmer testing:
I also ran into another issue that comes up a lot: what to do with existing tests? Those tests almost exclusively test parsing of line numbers, method names, and filenames out of a single frame. They take advantage of the old interface to "cheat". Here's an example (slightly modified in ways irrelevant to the story):
public void testJdkConstructor() {
String jdkConstructor =
"\tat java.util.StackPrinter.<init>(StackPrinter.java:1)\n";
TraceCaller tc = new TraceCaller(jdkConstructor, 0);
assert(tc.methodName.equals("StackPrinter.<init>"));
assert(tc.fileName.equals("StackPrinter.java"));
assert(tc.lineNumber.equals("1"));
}
Instead of using a real stack dump, I only gave the old TraceCaller
constructor one frame and told it to skip zero frames to find the
frame to parse. That was convenient with the old interface. To
make these tests work in the new interface, I have to convert
them to use a full stack dump. Is it worth it?
Well, yes, obviously. Not only is it easy to do, but these tests are quite valuable. The frame-parsing code will change a lot in the future, as the Trace code is ported to new VMs. It's important that changes to handle a new stack frame format don't break Trace's ability to handle old ones. The tests are key to achieving that.
But I mention the issue because I've noticed that many programmers are a bit careless about it. Some can't bear to throw away tests, even if the value of the test (in terms of likely bugs found) is far less than the cost of upgrading them. Others throw away tests because upgrading tests is boring, even if the upgrade is worthwhile. (Or, as seems to happen often, people dutifully upgrade the tests... and upgrade the tests... and upgrade the tests - until finally they can't stand it any more and throw them away. Sometimes they don't think they're throwing them away. They think they're setting them aside "just for now".)
At this point, I knew my tests would look like this:
public void testSomething() {
String msg = "XXX";
TraceCaller tc = new TraceCaller(msg);
assert(tc.methodName.equals("XXX"));
assert(tc.fileName.equals("XXX"));
assert(tc.lineNumber.equals("XXX"));
}
The question is what should be in those XXX's.
I always answer that question by making a list of "test
ideas". I write down all the things I intend to test before
I launch into writing test code. I give my TraceCaller
list below. You'll notice it's hard to follow. In fact, even I
don't know today what on earth I meant by "check for small
buffer overrun". But that's OK. Such a list is just to
remind me of test ideas for the duration of the task. It's not
intended to be read by someone else. It's not intended to be kept.
It's scratch paper. I use it because I find I do a more complete
job if I write ideas down first than if I implement test ideas as
soon as I have them.
Stack walking:
// A normal stack for recordTraceMessage - sun stack format
// Two recordTraceMessages from two different trace calls in the stack.
the known error cases:
// recordTraceMessage at the bottom of the stack
// recordTraceMessage duplicated at the bottom of the stack.
Some hypothetical error cases:
// recordTraceMessage at the top of the stack (nothing above it)
// recordTraceMessage at the top of the stack with one frame above it.
// recordTraceMessage at the top with exactly two frames above it
// (check for small buffer overrun. <this is not an error case>
// recordTraceMessage is not in the stack
// stack has only one element (not RecordTraceMessage)
// stack has no elements (only leader text)
// stack is empty string
Let me explain a few of those last test ideas. Over the years, I've been collecting a catalog of test ideas that are broadly useful. The first was in my book, The Craft of Software Testing. I later shortened it a bit. My latest version is only one page long. (I find that shorter catalogs get used more.)
TraceCaller provides a good example of the use of
a catalog. TraceCaller searches for recordTraceMessage.
In code that searches, the following ideas are useful:
TraceCaller, because the stack
dump it's given is guaranteed to contain recordTraceMessage...
or is it? After all, sometimes the compiler duplicates
the recordTraceMessage frame. Might it not
also delete it entirely? In that case, TraceCaller
should fail gracefully by setting the location to "method?"/"file?"/"line?",
not do something like blow up. recordTraceMessage frame, and
one where a user's trace message causes Trace.java to
itself post a trace message. However, if I had overlooked
that second one, there's a chance the catalog entry would
have reminded me. It happens sometimes.Once I have the list of test ideas, it's straightforward to translate them into code. As I translate each one, I cross it off the list. So, for example, the first test idea leads to this test:
// Standard trace message, Sun stack.
public void testStackWalkNormalSun() {
String msg =
"java.lang.Exception\n"+
"\tat org.erights.e.develop.trace.TraceMessage.<init>(TraceMessage.java:88)\n"+
"\tat org.erights.e.develop.trace.Trace.recordTraceMessageXyzzY(Trace.java:348)\n"+
"\tat org.erights.e.develop.trace.Trace.errorm(Trace.java:213)\n"+
"\tat Dump.main(Dump.java:18)\n";
TraceCaller tc = new TraceCaller(msg);
assert(tc.methodName.equals("Dump.main"));
assert(tc.fileName.equals("Dump.java"));
assert(tc.lineNumber.equals("18"));
}
You may notice a couple of odd things about this test.
recordTraceMessage is called recordTraceMessageXyzzY.
I explain why here. It's not
particularly important. As is often the case, implementing the tests gave me more test ideas. I wrote those into the list as I thought of them. Here's what I thought of:
// Lines end in \r\n
// Last frame on the stack has no terminating \n.
// Check that searching for recordTraceMessage is not dependent on the package name (e.develop.goobble3ydouyag.Trace.)
I thought of the first two as I was looking at the newline marks in the stack dumps and was reminded of one of the differences between Windows and Unix. (Test ideas from those differences really belong in a catalog, but I haven't done that.)
Notice an important thing about the new test ideas: they can easily be merged into tests written for other reasons. So, for example, the following one test implements all three of the above ideas:
// Standard trace message, Sun stack.
// Small variation on above: CRLFs instead of terminating LFs, and
// no terminating LF at the top of the stack. Also changing package
// names to flush out package dependencies.
public void testStackWalkCRLFSun() {
String msg =
"java.lang.Exception\r\n"+
"\tat X.TraceMessage.(TraceMessage.java:88)\r\n"+
"\tat X.recordTraceMessageXyzzY(Trace.java:348)\r\n"+
"\tat X.errorm(Trace.java:213)\r\n"+
"\tat Dump.main(Dump.java:18)";
TraceCaller tc = new TraceCaller(msg);
assert(tc.methodName.equals("Dump.main"));
assert(tc.fileName.equals("Dump.java"));
assert(tc.lineNumber.equals("18"));
}
Doubling up saves work. It does make it a little more different to create new tests by copying and tweaking old tests. But I think that's good. I'm always sure that I've overlooked some test ideas. The more different each test is from the others, the more likely it will stumble over a bug by sheer dumb luck. I'm a big fan of dumb luck; at least, I'd rather have luck working on my side than against me. So I don't mind slightly more complex tests.
I also have a habit of injecting "unnecessary" variety into tests. For example, I might change package names in the stack dump even though I don't think that makes a difference.
I don't get obsessive about this. I don't make very complex tests or insist on great amounts of variety. But I add complexity and variety when it's easy to do.
I proceeded in this way until I had 22 tests. (That number includes the upgraded frame-parsing tests.)
Having implemented the tests, I wrote the code. It was pretty straightforward. When I finished the code, I ran the tests.
Almost every one of them failed. Oops.
The problem was simple. I had the code that found the recordTraceMessage
frame. I had the code that parsed the frame. I'd forgotten the
code that moved from the recordTraceMessage frame to
the frame that really posted the message. (The ones that didn't
fail were those for pathologically broken stack dumps, such as
the test where the stack dump is an empty string.)
One simple fix later, 20 of the 22 tests passed. One of the failures was a typo in the test, which took only a few seconds to discover.
The other was a failure I expected because I'd deferred implementing one special case. After I saw everything else pass, I added the remaining special case and the last test passed.
You can find this version of my test suite here.
At this point, I digressed to write some other tests for other purposes. Much to my despair, one of those tests printed an incorrect location (even though it was written to test something else).
I looked at the stack dump. It looked like this:
java.lang.Exception
at com.visibleworkings.trace.Trace.recordTraceMessageXyzzY(Trace.java, Compiled Code)
at java.lang.Exception.<init>(Exception.java, Compiled Code)
at com.visibleworkings.trace.TraceMessage.<init>(TraceMessage.java, Compiled Code)
at com.visibleworkings.trace.Trace.recordTraceMessageXyzzY(Trace.java, Compiled Code)
at com.visibleworkings.trace.Trace.worldm(Trace.java, Compiled Code)
at Threadzilla.run(T2.java, Compiled Code)
Those two most recent frames are completely bogus. There is no
way that the java.lang.Exception constructor calls recordTraceMessage,
and the Exception constructor shouldn't be in the stack dump
anyway.
Oh well. I converted this stack dump into another test case, changed the code to handle it, and reran all the tests. They passed.
I find that my code benefits when I let it sit for a while, then come back and reread it. That's when I write most of my comments (and usually greatly improve those comments I wrote earlier). I will often change names that seemed to make sense at the time but no longer do. And I sometimes realize other ways in which the code could be improved.
And, finally, I usually get new test ideas. (That also happens when I'm first writing the code. In that case, I add the new test idea to my list and implement it either immediately or as soon as I finish the snippet of code I'm working on. My notes for this change don't show new ideas during coding, which is unusual.)
One thing I do when cleaning up the code is check that my
tests cause every boolean expression to evaluate to both true and
false. (That includes subexpressions: for example, given "if
(A && B)", both A and B
must have been both true and false.) I also check if my code has
had to cope with all return values. For example, TraceCaller
calls String.indexOf, which normally returns a
character position. But it can also return a -1 if the thing
being sought can't be found. I'd like to see TraceCaller
handle both returns from each use of String.indexOf.
I also check whether all exceptions that called code could throw
have in fact been thrown.
Anything I missed is a new test idea. As with all test ideas, I might choose not to write the test. But I want to make that decision consciously, not make it by default because I overlooked something.
As is typical, my tests didn't miss any boolean conditions. But I did miss two exceptions. Here's how.
TraceCaller works by initializing the three
fields to the default values "method?", "file?",
and "line?". It then tries to parse out the real values.
If the parse fails at any point, the code throws an exception.
The top-level code catches the exception and returns from the
constructor, leaving one or more of the fields with its initial
value.
Here's a sample of such code:
retval.start = stackDump.lastIndexOf('\n', middle);
quitIf(retval.start == -1);
retval.start++;
retval.pastEnd = stackDump.indexOf('\n', middle);
quitIf(retval.pastEnd == -1);
return retval;
The quitIf method is tidier than spreading
statements like these throughout the code:
if (retval.start == -1) throw new Exception();
I found two quitIf calls that had never thrown an
exception. Neither of them made for a particularly compelling
test. Neither corresponded to likely input, and it was pretty
clear that the code would work if the exception were thrown.
Nevertheless, I did write four tests, mainly to have an excuse to
talk about getting test ideas from boolean expressions and method
results. Those tests can be found here.
Note that I got three tests from one of the missed exceptions. That's pretty typical. Here's how it happened.
One of the quitIf calls would throw an exception
for this stack dump:
at com.visibleworkings.trace.Trace.recordTraceMessageXyzzY(Trace.java, Compiled Code) at com.visibleworkings.trace.Trace.worldm(Trace.java, Compiled Code) at Threadzilla.run(T2.java, Compiled Code)
Not only is the TraceMessage constructor missing,
so is what I'll call the "exception header":
java.lang.Exception
That would be a pretty outlandishly broken stack. But thinking about it gave me two more plausible ideas. The above stack dump has two oddities - a dropped frame and a dropped exception header. What if only the exception header is dropped?
at com.visibleworkings.trace.TraceMessage.<init>(TraceMessage.java, Compiled Code) at com.visibleworkings.trace.Trace.recordTraceMessageXyzzY(Trace.java, Compiled Code) at com.visibleworkings.trace.Trace.worldm(Trace.java, Compiled Code) at Threadzilla.run(T2.java, Compiled Code)
And what if the exception header is there, but in a completely different format?
We are here in exception land Here are the contents... at com.visibleworkings.trace.TraceMessage.<init>(TraceMessage.java, Compiled Code) at com.visibleworkings.trace.Trace.recordTraceMessageXyzzY(Trace.java, Compiled Code) at com.visibleworkings.trace.Trace.worldm(Trace.java, Compiled Code) at Threadzilla.run(T2.java, Compiled Code)
The code is oblivious to all these differences, because the
exception header is irrelevant. TraceCaller will
search right past it. But sometimes this sort of free play of
test ideas makes you realize that something you thought
was irrelevant is in fact entirely relevant. It's important to
expand your thinking beyond just what the code happens to do.
That's because a large percentage of bugs - maybe 30-40% - are
caused when the programmer overlooks
some special case.
I don't know yet. As bugs are reported, I'll note them here.
Be the first person to add a comment in the
Wiki Forum at page TraceDeveloperTesting.
(The Forum is explained in its FrontPage.)
Comments to testingcraft-discuss@egroups.com