There are a thousand ways one can make junit test cases fail sporadically and inexplicably. Here is one such encounter that happened a few months ago.
A test case was measuring ‘timestamp proximity’.
Sample code under test:
long timestamp = System.currentTimeMillis();
return SomePojo.<O>customBuilder()
.requestId(UUID.randomUUID() + "-" + timestamp)
.timestamp(timestamp);
As seen, it generates a UUID concatenated with a timestamp. The unit test was validating that the timestamp was ‘freshly generated’ and is within an acceptable range (=20ms):
String[] tokens = requestId.split("-");
assertThat(Double.valueOf(tokens[tokens.length -1]), IsCloseTo.closeTo(System.currentTimeMillis(), 20));
So far so good. It just worked. And 20ms is a wide enough duration.
But it started failing after migrating to JDK15.
Suddenly, the duration 20ms was not enough anymore.
Turns out, the order of execution of the tests was no longer the same as before.
To validate what’s the order of execution, by default it relies on the order of the methods that the JDK provides. This can be tested out with the below sample code:
import java.lang.reflect.Method;
public class ReflectDemo {
public static void main(String[] args) {
Class<?> clazz = SampleClass.class;
Method[] methods = clazz.getDeclaredMethods();
System.out.println("Methods of class: " + clazz.getName());
for (Method method : methods) {
System.out.println(method.getName() + " - Return type: " + method.getReturnType().getSimpleName());
}
}
}
// A sample class with some methods
class SampleClass {
public void sayHello() {
System.out.println("Hello");
}
private int add(int a, int b) {
return a + b;
}
protected void doSomething() {
// do something
}
}
When run with JDK 17:
Methods of class: SampleClass
add - Return type: int
doSomething - Return type: void
sayHello - Return type: void
When run with JDK 8:
Methods of class: SampleClass
add - Return type: int
sayHello - Return type: void
doSomething - Return type: void
Plus, this doesn’t stay static and it may depend on JVM implementation.
But, we weren’t using any ‘state’ that carries over from one test to another, so how can it effect?
Well, maybe not so obvious, but we still do have a ‘state’ that carries over. And thats the classloader.
So, what was happening was, when this particular test was not the first test to be executed, the UUID class was well loaded. However, when this became the first test to be executed, it did take some extra time to load the class and hence, sometimes it failed that 20ms bound check.
The fix
I could fix it with enforcing the tests execution order. But I guess that wasn’t the cleaner way to do, as that can thrown subtle bugs like these under the carpet.
The other way to fix it was obviously letting the timestamp get recorded after the class is loaded.
So, the changed code looked like this:
UUID uuid = UUID.randomUUID();
long timestamp = System.currentTimeMillis();
return SomePojo.<O>customBuilder()
.requestId(uuid + "-" + timestamp)
.timestamp(timestamp);
There! Fixed it.