Refactoring Time-Related Test

This is a short story of a bad "refactor" of test code. In Poland we say, that "dobrymi chęciami piekło brukowano", which basically means, that trying to do something good can lead to really bad results. Well, I tried to do something good and I failed. Let us take a closer look.

It all started when I came upon a test class. While browsing it I noticed that many tests have very similar beginning. Like this:

@Test
public void shouldCreateClientForPlanX() {
    // given
    LocalDateTime now = LocalDateTime.now(ZoneOffset.UTC);
    LocalDateTime createdOn = now.minusDays(1);

    ...
}

or

@Test
public void shouldCreateClientForSomeOtherPlan() {
    // given
    LocalDateTime now = LocalDateTime.now(ZoneOffset.UTC);
    LocalDateTime createdOn = now.minusDays(7);

    ...
}

... few more methods similar to the ones above

In many "given" sections there were some time-related operations, i.e. the now was calculated. Aha! An opportunity to make tests more readable! I can move it so some common place (maybe setUp method?) and avoid repeating this one line of code on every occasion. Hurray, let me do it.

And I did. It went pretty smoothly. IDE helped and after short time the code looked like this:

private static final LocalDateTime NOW = LocalDateTime.now(ZoneOffset.UTC);

@Test
public void shouldCreateClientForPlanX() {
    // given
    LocalDateTime createdOn = NOW.minusDays(1);

    ...
}

@Test
public void shouldCreateClientForSomeOtherPlan() {
    // given
    LocalDateTime createdOn = NOW.minusDays(7);

    ...
}

... few more methods similar to the ones above

Is it better? Well, not much difference, but I would say it is. NOW is pretty understandable and by using it I have shortened the "given" section by one line.

So I said to myself "good job, mate!". I run the tests. All passed as expected. I pushed the code to the repo. The CI server built the tests once again. All green. Good.

And it should be the end of the story but it ain't so. Few days later one of my colleagues told me that this tests is failing and that I should fix it because it seems to be related to the last changes I made. What the hell?! Obviously it can't be. Such a simple refactor... no, it definitely wasn't my fault. But anyway, I had to take a closer look at what is going on.

And it occurred that it was my "refactor" after all! The problem was, that in some tests this now variable was used like this:

assertThat(client.getCreatedTime()
    .truncatedTo(ChronoUnit.MINUTES))
    .isEqualTo(now.truncatedTo(ChronoUnit.MINUTES));

where now is the local variable (which means it was created few lines above this line and few milliseconds before this line was executed).

But after my refactor the line has changed to:

assertThat(client.getCreatedTime()
    .truncatedTo(ChronoUnit.MINUTES))
    .isEqualTo(NOW.truncatedTo(ChronoUnit.MINUTES));

using NOW static field created some more milliseconds ago.

Now if it happened that the tests was started right before the clock ticked another minute it was possible that there was a one minute difference between NOW and the time that client was created. It was happening very rarely but it was. Of course, such situation could also happen with the now local variable being used, but that would be much less likely.

Any lessons learned? Yes, I guess so.

1) Do not refactor automatically. Think about every line of code you change.
2) Running a time-related test once, or twice, or even 10 times can not prove the test is well-written.

P.S. I will probably put this story to the next edition of my "Bad Tests, Good Tests" book. If you have any interesting stories about test share them with me and they will also end up in this book. Glory and fame awaits you! ;)

 
 
 
This used to be my blog. I moved to http://tomek.kaczanowscy.pl long time ago.

 
 
 

Please comment using