Piper at the Gates of Dawn

What's the best way to run integration tests for separate, discrete services?

In an attempt to decouple the stack, a service has been pulled out into a separate project. To run the integration tests of this discrete project, the stack needs to be brought up. We'd like to automate this so we used Java's ProcessBuilder thus:

ProcessBuilder processBuilder = new ProcessBuilder(command);

Process process = processBuilder.start();

for each module that needs to start up. We'd wait for some character sequence like "Module XXX started!" before starting the next.

All was going well until somebody changed the logging file in the module that we start up this way. The (RMI) thread that serviced our request was hanging and we saw this in JConsole:

Name: RMI TCP Connection(2)-154.1.225.59

State: RUNNABLE

Total blocked: 0 Total waited: 0

Stack trace:

java.io.FileOutputStream.writeBytes(Native Method)

java.io.FileOutputStream.write(FileOutputStream.java:260)

java.io.BufferedOutputStream.write(BufferedOutputStream.java:105)

- locked java.io.BufferedOutputStream@cf0384

java.io.PrintStream.write(PrintStream.java:430)

- locked java.io.PrintStream@efe617

sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202)

sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:263)

sun.nio.cs.StreamEncoder.write(StreamEncoder.java:106)

- locked java.io.OutputStreamWriter@1eb1670

java.io.OutputStreamWriter.write(OutputStreamWriter.java:190)

java.io.BufferedWriter.flushBuffer(BufferedWriter.java:111)

- locked java.io.OutputStreamWriter@1eb1670

java.io.PrintStream.write(PrintStream.java:476)

- locked java.io.PrintStream@efe617

java.io.PrintStream.print(PrintStream.java:619)

java.io.PrintStream.println(PrintStream.java:756)

- locked java.io.PrintStream@efe617

org.hibernate.jdbc.AbstractBatcher.log(AbstractBatcher.java:396)

In this version of Hibernate (3.2.6) this line was just a System.out.println call. Why on earth would this cause the thread to block forever?

The thread was stuck in native code so was there something wrong with my JVM (1.6.0_20 on Windows)? Would looking at file handles show some sort of contention? Would it be OK on a *Nix machine?

Putting a breakpoint in this Hibernate code only confused me further. The first time Hibernate hits this System.out.println call, it is executed without problem. It's only the second time that the thread hangs forever.

Whenever something works fine for a while then stops working for good suggests a resource is being exhausted. It took me some Googling before realizing that the pipe's buffers were filling up - but not until the second execution of System.out.println.

When you start another process via the JVM, you can't then ignore it. It may send data to an output stream (for example, just printing to the console). Some thread needs to drain this stream even if it does nothing with the data - the notion of a StreamGobbler.

Obvious in retrospect but not immediately apparent when you forget and you're confronted by this behaviour.