thekua.com@work

Some application logging is important enough to put regressions tests in place. For instance, when you shell out to other programs and you want to monitor the amount of time it takes. In this entry I’m going to demonstrate how you might test that you are correctly logging out the time taken to do some long running work. I’m going to assume that you already have a Clock concept in the system.

Let’s assume we’re trying to test the following block of code:

public void doSomeWork(Clock clock) {
  DateTime startTime = clock.now();
  executeSomeLongRunningWork();
  DateTime endTime = clock.now();
  long timeTaken = endTime.minus(startTime.getMillis()).getMillis();
  LOG.log(Level.INFO, "Time taken was %sms", timeTaken);
}

One approach would be refactor the above code, replacing the Clock with a StopWatch but I’m going to show a technique for testing this code without changing it. Instead, we are going to inject an AutomaticallyForwardingClock. Here’s the implementation:

public class AutomaticallyMovingForwardClock implements Clock {
  private final int periodToMoveForwardsInMs;
  private DateTime now;

  public AutomaticallyMovingForwardClock(DateTime initialStartTime,
      int periodToMoveForwardsInMs) {
    this.now = initialStartTime;
    this.periodToMoveForwardsInMs = periodToMoveForwardsInMs;
  }

  public DateTime now() {
    DateTime result = now;
    now = now.plusMillis(periodToMoveForwardsInMs);
    return result;
  }
}

So whenever anyone asks the current time from the Clock, it automatically shifts time forward by the specified amount. Now we can write a test that looks like this:

@Test
public void shouldLogTimeTakenForProgramToExecute() throws Exception {
  int periodToMoveForwards = 5;
  Clock clock = new AutomaticallyMovingForwardClock(new DateTime(), periodToMoveForwards);
  doSomeWork(clock);

  long expectedDuration = periodToMoveForwards;
  assertThat(fetchLogEntry(), containsString("Time taken " + expectedDuration + "ms"));
}

A few notes from above:

• The test uses the Joda DateTime class.
• The test uses the Hamcrest API
• The test assumes you know how to retrieve the log message from a logger

Although I think that injecting a StopWatch is probably a better mechanism, I hope that this technique still proves useful for some people.

Comments(0)

Update (Feb 21): Thanks to some feedback from Taras and Lowell, the ThreadedRunner is the same as the java.util.concurrent.Executor class! I’ve updated the post to reflect this below. Thanks for the suggestion!

Unit testing threaded software can sometimes prove slightly cumbersome. Many of the examples on the net often show examples that tie a number of responsibilities together. It might be easy to see something like this:

  public class SomeExample {
    public void doSomeWork() {
      Runnable runnable = new Runnable() {
        public void run() {
          // do some long running work
        }
      };
      new Thread(runnable).start();
    }
  }

The thing about this class above is to realise what responsibilities it is mixing, including the new work they would like to (the item in Runnable), as well as how they would like to run it (the separate thread). It’s difficult to tease these two responsibilities apart the way it’s declared. The first thing I’d do is remove the dependency on the new thread. I’ll start by making use of the java.util.concurrent.Executor :

public interface Executor {
  void execute(Runnable runnable);
}

public class SingleThreadedExecutor implements Executor {
  public void execute(Runnable runnable) {
    runnable.run();
  }
}
public class NewThreadedExecutor implements Executor {
  public void execute(Runnable runnable) {
    new Thread(runnable).start();
  }
}

We’ll inject the SingleThreadedExecutor in our unit tests, so we only ever have one thread of execution, and we can rely on tests being consistently reproducible. We’ll inject the NewThreadedExecutor when we need to assemble our application for production. Here’s the step by step refactoring.

Wrap inside our new implementation

public class SomeExample {
  public void doSomeWork() {
    Runnable runnable = new Runnable() {
      public void run() {
        // do some long running work
      }
    };
    new NewThreadedExecutor().start(runnable);
  }
}

Inject instance via the constructor

public class SomeExample {
  private final NewThreadedExecutor executor;
  public SomeExample(NewThreadedExecutor executor) {
    this.executor = executor;
  }  

  public void doSomeWork() {
    Runnable runnable = new Runnable() {
      public void run() {
        // do some long running work
      }
    };
    executor.start(runnable);
  }
}

Replace specific with interface

public class SomeExample {
  private final Executor executor;
  public SomeExample(Executor executor) {
    this.executor = executor;
  }  

  public void doSomeWork() {
    Runnable runnable = new Runnable() {
      public void run() {
        // do some long running work
      }
    };
    executor.start(runnable);
  }
}

In the tests, you can now inject an instance of SingleThreadedExecutor, whilst in production mode, you use the NewThreadedExecutor.

Disclaimers
Of course, this still leaves your testing strategy incomplete where you do want to test your software with the number of threads that you do expect, particularly when you need to share state across different processes.

Comments(4)

It’s been a while since I’ve had to slice and dice legacy code. It reminds me how easily, non test driven code, slips into the abyss of tight coupling and the effort of retrofitting (unit) tests increasing in effort with time. Of course, I don’t believe TDD should be done all the time, but for most production code I do. In this entry, I’m going to use the Sprout Inner Class mechanism to demonstrate how to start making something that would have been untestable much more manageable.

The scenario
What we have below is the entry point into our program (i.e. a class with a main method). When I first encountered this class, it had too many responsibilities including, and not limited to, parsing command line options, some application logic, handling terminal signals, and wiring up all the objects for the program to start. Combined with an infinite working loop, you can imagine what a nightmare it was to unit test. Here’s the modified class, called RunningProgram representing the important parts of the class related to this walk through.

Our task: To reduce the number of responsibilities and test the body of the start method (we couldn’t simply extract method immediately due to the number of fields it modified)

package com.thekua.examples;

import sun.misc.Signal;
import sun.misc.SignalHandler;

public class RunningProgram implements SignalHandler {
	private boolean running = true;
	// some other fields

	public void start() {
		running = true;
		while (running) {
			// do some work (that we want to unit test)
			// it changes about ten fields depending on what condition
			// gets executed
		}
		// Finished doing some work
	}

	// it also had plenty of other methods

	public static void main(String [] args) {
		RunningProgram program = new RunningProgram();
		Signal.handle(new Signal("TERM"), program);
		Signal.handle(new Signal("INT"), program);
		program.start();
	}

	public void handle(Signal signal) {
	    // Program terminated by a signal
		running = false;
	}
}

Step 1: Understand the dependencies that make this test difficult to test
To get some level of functional testing around this program we had a number of timed triggers, watching for state modifications with a given timeout. Our problem was infinity itself, or rather, not sure when to interrupt infinity to watch for when the body of work inside the loop had finished its work once, twice, and not too early. We could have made it more complicated by introducing lifecycle listeners yet we hesitated at that option because we thought it would complicate the code too much.

We noticed the use of the running flag. We noticed it was the condition for whether or not we continued looping, and was also the trigger for a graceful shutdown using the sun.misc.Signal class. Notice that the running program implements the SignalHandler interface as a result. We thought that running behaviour of the RunningProgram could be extracted into a separate aspect.

Step 2: Encapsulate, encapsulate, encapsulate
Our first task, was to remove direct access to the running flag since the class modified it in two places. Sprout an inner class, and simply delegate to getters and setters and we might find we have a class that looks like:

package com.thekua.examples;

import sun.misc.Signal;
import sun.misc.SignalHandler;

public class RunningProgram implements SignalHandler {
    public static class RunningCondition {
	    private boolean running = true;

		boolean shouldContinue() {
		    return running;
		}

		public void stop() {
		    running = false;
		}
    }

	private RunningCondition condition = new RunningCondition();

	// some other fields

	public void start() {
		while (condition.shouldContinue()) {
			// do some work (that we want to unit test)
			// it changes about ten fields depending on what condition
			// gets executed
		}
		// Finished doing some work
	}

	// it also had plenty of other methods

	public static void main(String [] args) {
		RunningProgram program = new RunningProgram();
		Signal.handle(new Signal("TERM"), program);
		Signal.handle(new Signal("INT"), program);
		program.start();
	}

	public void handle(Signal signal) {
	    // Program terminated by a signal
		condition.stop();
	}
}

Moving the running flag to a separate class gives us a number of benefits. It lets us hide the implementation of how we handle running, and puts us down the road of clearly teasing apart the overloaded responsibilities.

Step 3: Consolidate related behaviour
It bothered me that the main program had the shutdown hook. That behaviour definitely felt strongly related to the RunningCondition. I felt it was a good thing to move it to the that class. We now have something that looks like:

package com.thekua.examples;

import sun.misc.Signal;
import sun.misc.SignalHandler;

public class RunningProgram {
    public static class RunningCondition implements SignalHandler {
	    private boolean running = true;

		boolean shouldContinue() {
		    return running;
		}

		public void handle(Signal signal) {
	        // Program terminated by a signal
			running = false;
	    }
    }

	private RunningCondition condition = new RunningCondition();

	// some other fields

	public void start() {
		while (condition.shouldContinue()) {
			// do some work (that we want to unit test)
			// it changes about ten fields depending on what condition
			// gets executed
		}
		// Finished doing some work
	}

	// it also had plenty of other methods

	public static void main(String [] args) {
		RunningProgram program = new RunningProgram();
		Signal.handle(new Signal("TERM"), program.condition);
		Signal.handle(new Signal("INT"), program.condition);
		program.start();
	}

}

Note that it is now the RunningCondition that now implements the SignalHandler interface (that we are using to register with the Signal

Step 3: Remove dependency chain
The difficulty with this class still exists. We cannot modify the RunningCondition of this program since it creates one for itself. Since I prefer Constructor Based Dependency Injection, I’m going to apply Introduce Parameter to Constructor, moving the field declaration to the constructor itself. Here it is what the class looks like now:

package com.thekua.examples;

import sun.misc.Signal;
import sun.misc.SignalHandler;

public class RunningProgram {
    public static class RunningCondition implements SignalHandler {
	    private boolean running = true;

		boolean shouldContinue() {
		    return running;
		}

		public void handle(Signal signal) {
	        // Program terminated by a signal
			running = false;
	    }
    }

	private final RunningCondition condition;

	public RunningProgram(RunningCondition condition) {
	    this.condition = condition;
	}

	// some other fields

	public void start() {
		while (condition.shouldContinue()) {
			// do some work (that we want to unit test)
			// it changes about ten fields depending on what condition
			// gets executed
		}
		// Finished doing some work
	}

	// it also had plenty of other methods

	public static void main(String [] args) {
		RunningProgram program = new RunningProgram(new RunningCondition());
		Signal.handle(new Signal("TERM"), program.condition);
		Signal.handle(new Signal("INT"), program.condition);
		program.start();
	}

}

Note that we are still bound to the implementation of the specific RunningCondition, so it’s time to apply Extract Interface, and understand what role that RunningCondition has. We chose the name, RunStrategy for the role name, and to help keep the names more aligned, we ended up renaming RunningCondition to RunLikeADaemonStrategy. Our code now looks like this:

package com.thekua.examples;

import sun.misc.Signal;
import sun.misc.SignalHandler;

public class RunningProgram {
    public static interface RunStrategy {
	    boolean shouldContinue();
	}

    public static class RunLikeADaemonStrategy implements SignalHandler, RunStrategy {
	    private boolean running = true;

		public boolean shouldContinue() {
		    return running;
		}

		public void handle(Signal signal) {
	        // Program terminated by a signal
		    running = false;
	    }
    }

	private final RunStrategy runStrategy;

	public RunningProgram(RunStrategy runStrategy) {
	    this.runStrategy = runStrategy;
	}

	// some other fields

	public void start() {
		while (runStrategy.shouldContinue()) {
			// do some work (that we want to unit test)
			// it changes about ten fields depending on what condition
			// gets executed
		}
		// Finished doing some work
	}

	// it also had plenty of other methods

	public static void main(String [] args) {
		RunLikeADaemonStrategy strategy = new RunLikeADaemonStrategy();
		RunningProgram program = new RunningProgram(strategy);
		Signal.handle(new Signal("TERM"), strategy);
		Signal.handle(new Signal("INT"), strategy);
		program.start();
	}
}

The best thing is that our RunningProgram no longer needs to know what happens if a terminate or interrupt signal is sent to the program. With simply a dependency on the RunStrategy we can know inject a fixed run strategy for tests that we ended up calling a RunNumberOfTimesStrategy. We also promoted the specific RunLikeADaemonStrategy to a full class (not an inner class).

Thanks for getting this far! Please leave a comment if you thought this was useful.

Comments(4)

Disclaimer: This technique does not work outside of programming. Do not try this on your neighbours, kids or pets…

What’s wrong with time dependent tests?
It’s easy to write tests that are far too flaky and intermittent. Worse yet, a quick fix often results in putting a pause to tests that make them drag out longer and longer. Alternatively, unneeded complexity is added to try to do smart things to poll for tests to time out.

What can we do about it?
I’m all about solutions, so I’m out about to outline the secret to controlling time (in at least unit tests). Here’s a situation you might recognise. Or not. Sorry to anyone vegetarian reading this entry.

We have a class called Beef that knows when it’s past its prime using the Joda Time libraries.

package com.thekua.examples;

import org.joda.time.DateTime;

public class Beef {
	private final DateTime expiryDate;

	public Beef(DateTime expiryDate) {
		this.expiryDate = expiryDate;
	}

	public boolean isPastItsPrime() {
		DateTime now = new DateTime(); // Notice this line?
		return now.isAfter(expiryDate);
	}
}

Surprise, surprise. We also have a unit test for it:

package com.thekua.examples;

import static org.junit.Assert.assertTrue;
import org.joda.time.DateTime;
import org.junit.Test;

public class BeefTest {
	@Test
	public void shouldBePastItsPrimeWhenExpiryDateIsPast() throws Exception {
		int timeToPassForExpiry = 100;

		Beef beef = new Beef(new DateTime().plus(timeToPassForExpiry));

		Thread.sleep(timeToPassForExpiry * 2); // Sleep? Bleh...

		assertTrue(beef.isPastItsPrime());
	}
}

Step 1: Contain time (in an object of course)
The first step is to contain all the use of time concepts behind an object. Don’t even try to call this class a TimeProvider. It’s a Clock okay? (I’m sure I used to call it that in the past as well, so don’t worry!). The responsibility of the Clock is to tell us the time. Here’s what it looks like:

package com.thekua.examples;

import org.joda.time.DateTime;

public interface Clock {
	DateTime now();
}

In order to support the system working as normally, we are going to introduce the SystemClock. I sometimes call this a RealClock. It looks a bit like this:

package com.thekua.examples;

import org.joda.time.DateTime;

public class SystemClock implements Clock {
	public DateTime now() {
		return new DateTime();
	}
}

We are now going to let our Beef now depend on our Clock concept. It should now look like this:

package com.thekua.examples;

import org.joda.time.DateTime;

public class Beef {
	private final DateTime expiryDate;
	private final Clock clock;

	public Beef(DateTime expiryDate, Clock clock) {
		this.expiryDate = expiryDate;
		this.clock = clock;
	}

	public boolean isPastItsPrime() {
		DateTime now = clock.now();
		return now.isAfter(expiryDate);
	}
}

If you wanted to, the step by step refactoring would look like:

1. Replace new DateTime() with new SystemClock().now()
2. Replace new instance with field
3. Instantiate new field in constructor

We’d use the RealClock in both the code that creates the Beef as well as our test. Our test should look like…

package com.thekua.examples;

import static org.junit.Assert.assertTrue;
import org.junit.Test;

public class BeefTest {
	@Test
	public void shouldBePastItsPrimeWhenExpiryDateIsPast() throws Exception {
		int timeToPassForExpiry = 100;
		SystemClock clock = new SystemClock();

		Beef beef = new Beef(clock.now().plus(timeToPassForExpiry), clock);

		Thread.sleep(timeToPassForExpiry * 2);

		assertTrue(beef.isPastItsPrime());
	}
}

Step 2: Change the flow of time in tests
Now that we have the production code dependent on an abstract notion of time, and our test still working, we now want to substitute the RealClock with another object that allows us to shift time for tests. I’m going to call it the ControlledClock. Its responsibility is to control the flow of time. For the purposes of this example, we’re only going to allow time to flow forward (and ensure tests use relative times instead of absolute). You might vary it if you needed very precise dates and times. Note the new method forwardTimeInMillis.

package com.thekua.examples;

import org.joda.time.DateTime;

public class ControlledClock implements Clock {
	private DateTime now = new DateTime();

	public DateTime now() {
		return now;
	}	

	public void forwardTimeInMillis(long milliseconds) {
		now = now.plus(milliseconds);
	}
}

Now we can use this new concept in our tests, and replace the way that we previously forwarded time (with the Thread.sleep) with our new class. Here’s what our final test looks like now:

package com.thekua.examples;

import static org.junit.Assert.assertTrue;
import org.junit.Test;

public class BeefTest {
	@Test
	public void shouldBePastItsPrimeWhenExpiryDateIsPast() throws Exception {
		int timeToPassForExpiry = 100;
		ControlledClock clock = new ControlledClock();

		Beef beef = new Beef(clock.now().plus(timeToPassForExpiry), clock);

		clock.forwardTimeInMillis(timeToPassForExpiry * 2);

		assertTrue(beef.isPastItsPrime());
	}
}

We can even further improve this test to be more specific by forwarding time by simply adding one rather than multiplying twice.

Step 3: Save time (and get some real sleep)
Although this is a pretty trivial example of a single use of time dependent tests, it shouldn’t take too much effort to introduce this concept to any classes that depend on time. Not only will you save yourself heart-ache with either flaky, broken tests, but you should also save yourself the waiting time you’d otherwise need to introduce, leading to faster test execution, and that wonderful thing of fast feedback.

Enjoy! Let me know what you thought of this by leaving a comment.

Comments(8)

I’ve always been a big fan of Picocontainer because it has a lovely programmatic interface as an IoC container, and I generally value programmatic APIs over external representations, particularly for config files (note that it doesn’t mean external representations aren’t useful).

Unfortunately the followers of Spring love writing their code in XML, and many of their examples don’t show what you need to do to wire up all their examples declaratively in code. I spent some time trying to work out how to do some things.

Bean with an id ‘myBean’

<bean id="myBean" class="com.thekua.example.SomeClass">

in code:

GenericBeanDefinition someClassDefinition = BeanDefinitionBuilder.rootBeanDefinition(SomeClass.class).getBeanDefinition();
getDefaultListableBeanFactory().register("myBean", someClassDefinition);

Links that I used:

• Programmatically Build A Spring Application Context
• Programmatic Configuration in Spring

I’ll add more examples for the more complicated items later.

Comments(8)

I fixed a bug yesterday caused by a loop that terminated too early. It took me a while to understand the fact that it was terminating too early, and I realised that I’ve never written this type of bug because of the way that I tend to write code. Basically, the method looked like this:

public void someMethod() {
   for ( String key : keys ) {
       if (someCondition()) {
         return;
       }
       doSomeProcessingForThe(key);
   }
}

As you can see, the innocent looking return statement breaks out of the entire method, and what they really wanted was a continue statement instead. Note that TDD had been applied to this codebase, and it’s just another reminder that driving your code with tests isn’t enough (you also want to think of ensuring you write more comprehensive tests, particularly for loops).

I’m writing this post because I though it’s interesting that I realised a certain coding style removes (and possibly adds) a whole class of bugs. Had I been writing the code to start with, I probably would have avoided the use of the return (and/or continue) statement resulting in the following code:

public void someMethod() {
   for ( String key : keys ) {
       if (!someCondition()) {
         doSomeProcessingForThe(key);
       }
   }
}

Prevention is easy with tools like checkstyle, PMD or findbugs (and maybe some of them already check for this). If not, I think it’d be easy to add.

Comments(4)

I tried looking around on the Internet for a way from code, to get the arguments passed to the JVM itself, rather than environment properties, system properties, and program arguments. As of Java 5, apparently it got a whole lot easy in code than before with the java.lang.management.ManagementFactory.

Testing to see if you have a particular JVM argument is easy with a function like:

public boolean hasJvmArgument(String argument) {
  List arguments = ManagementFactory.getRuntimeMXBean().getInputArguments();
  return arguments.contains(argument);
}

Why would you want to do that?
For some systems, it’s critical the system operates under a specially configured environment. In our current system, for example, we have a health check that runs a series of tests to validate those assumptions still hold true. To achieve our performance targets, it’s integral our application starts with the correct JVM settings, and even with automation in place, we potentially have mistakes. Fortunately with the code above, we can simply add a JvmHasCorrectSettingsCheck to guarantee the application never gets deployed under the wrong circumstances.