A Cautionary Tale of Ant JUnit Fork Mode

My Oddjob build was taking over half an hour on my aging laptop. This is too much I thought…

Either I fix the build or buy a new laptop.

I started to look at the build and noticed most of the time was running the tests. A close look at the junit task configuration revealed I had forkyes‘ but no forkMode which was defaulting to ‘perTest‘. What if I changed this to ‘once‘?

		<junit printsummary="on" haltonfailure="no" 
				failureproperty="junit.failure"
				fork="yes" forkmode="once" 
				maxmemory="2G">
			<classpath>
				<pathelement location="${build.test.classes}" />
			</classpath>
			<classpath>
				<pathelement location="${java.home}/../lib/tools.jar"/>
			</classpath>
			<classpath refid="test-classpath"/>
			<batchtest todir="${test.reports}">
				<fileset dir="${build.test.classes}">
					<include name="**/test/*TestCase.class"/>
					<include name="**/*Test.class" />
					<exclude name="**/AllTest.class" />
					<exclude name="**/*$$*Test.class" />
				</fileset>
			</batchtest>
			<formatter type="xml" />
			<sysproperty key="basedir" value="${basedir}"/>
			<sysproperty key="oddjob.home" value="${oddjob.home}"/>
			<sysproperty key="ant.file" value="${ant.file}"/>
		</junit>

Everything broke.

OK, not quite everything but everything that was testing what Oddjob wrote to System.out. Oddjob changes System.out so that it can display the console of local and remote processes. This same mechanism is used by the tests to validate output. After getting no inspiration from Google, I thought…

Either I debug the Ant source code, or I buy a new laptop.

The Ant source code is quite easy to follow, and within a few hours I had picture of what was going on. The JUnit task itself replaces System.out so that it can pass the output to the formatters, and this happens on a per test case basis. So my own static System.out was being replaced by the second test that ran and not getting any further output. So…

Either I change the console capture system to initialise with each instance of Oddjob, or I buy a new laptop.

I introduced a new class to handle the initialisation of console capture with cleanup so that Oddjob and tests could be a good citizens and replace System.out when they were done. I needed to change a few dozen references from the old static field to the new class method but a few more hours later all the broken tests were now passing and the build was running in under fifteen minutes.

The build was however failing intermittently on one test that had nothing to do with System.out. It was failing cleaning up a file. I needed some logging to understand why. No Log4j output in my test? Am I going mad? I changed forkMode back to perTest and I got output. The same thing that was affecting Oddjob’s console capture was affecting Log4j. Google was some help here and I found a mailing list question and a bug report both relating to this.

The solution is to change log4j.properties to include:

log4j.appender.stdout.follow=true

I added this and once again I had Log4j output. Every test for console output now failed because it had Log4j output in it. I swore. The tests relied on Log4j being initialised before Oddjob so binding to System.out before Oddjob changed it. Oddjob would only capture output written to its System.out and missed all console logging. However with this configuration change, Log4j was following System.out and writing to Oddjob’s version once it was set.

Either I change my tests to change the console logging level before and after console capture or I buy a new laptop.

Changing log level wasn’t to hard with this helper class, but ensuring log level was restored correctly involved adding a try block to about 80 tests. Another few hours later I had Log4j logging, console capture tests passing and a build that was running in under fifteen minutes.

And my failing test? No idea – I added a try 3 times loop to the file delete. Some times you’ve just got to move on…

What a palaver just for one tiny attribute! After all that arduous work I felt I deserved a reward – so I bought a new laptop.

Java Parallel Runtime Execs Waiting for Each Other?!

Several Oddjob users have reported that, when running several execs in parallel on Windows, they all appeared to wait for each other to complete. The issue was easy to reproduce using this Oddjob configuration:

<oddjob>
  <job>
    <parallel>
      <jobs>
        <exec redirectStderr="true"><![CDATA[TestJob.cmd 2]]></exec>
        <exec redirectStderr="true"><![CDATA[TestJob.cmd 10]]></exec>
      </jobs>
    </parallel>
  </job>
</oddjob>

Where TestJob.cmd is:

ping -n %1 127.0.0.1
echo Finished pinging for %1.
exit 0

The problem can be seen here:

Parallel Exec Jobs

From the console of the first Exec Job it has clearly finished but its icon is still showing as Executing.

Java’s native process support is notoriously flaky, especially on Windows, and was the prime suspect. However, first I had to eliminate Oddjob from the enquiry. Here is some simple Java code that reproduces the problem:

public class ExecMain {

	static class Exec implements Runnable {
		private final String waitSeconds;

		Exec(String waitSeconds) {
			this.waitSeconds = waitSeconds;
		}

		@Override
		public void run() {
			long startTime = System.currentTimeMillis();

			final ByteArrayOutputStream captureOutput = new ByteArrayOutputStream();

			ProcessBuilder processBuilder = 
					new ProcessBuilder("TestJob.cmd", waitSeconds);
			processBuilder.redirectErrorStream(true);

			try {
				final Process process = processBuilder.start();
				Thread t = new Thread(new Runnable() {
					@Override
					public void run() {				
						copy(process.getInputStream(), captureOutput);
					}
				});
				t.start();
				process.waitFor();
				System.out.println("Process for TestJob.cmd " + waitSeconds + 
						" finished in " + secondsFrom(startTime) + " seconds.");
				t.join();
				System.out.println("Output thread for TestJob.cmd " + waitSeconds + 
						" joined after " + secondsFrom(startTime) + " seconds.");
			}
			catch (InterruptedException | IOException e) {
				throw new RuntimeException(e);
			}
		}

		void copy(InputStream from, OutputStream to) {
			byte[] buf = new byte[0x0400];
			try {
				while (true) {
					int r = from.read(buf);
					if (r == -1) {
						break;
					}
					to.write(buf, 0, r);
				}
			}
			catch (IOException e) {
				throw new RuntimeException(e);
			}
		}

		int secondsFrom(long startMillis) {
			return Math.round((System.currentTimeMillis() - startMillis) / 1000);
		}		
	}

	public static void main(String... args) {

		new Thread(new Exec("2")).start();
		new Thread(new Exec("10")).start();
	}
}

And here’s the output:

Process for TestJob.cmd 2 finished in 1 seconds.
Output thread for TestJob.cmd 2 joined after 9 seconds.
Process for TestJob.cmd 10 finished in 9 seconds.
Output thread for TestJob.cmd 10 joined after 9 seconds.

We can see that the process ends as expected after a second, but joining on the stream copying thread doesn’t happen until the sibling process has finished. This can only be if the first processes output stream isn’t being closed. Is it waiting for its siblings process output stream to close too?

Hours of Googling prove fruitless. Then by happenstance, I run my sample against Java 8. It works as expected. Off to the Java bug database – nothing obvious. Oddjob is currently supported on Java 7 and above so I downloaded the latest Java 7u80 release just to see, and it works to. Here is the correct output:

Process for TestJob.cmd 2 finished in 1 seconds.
Output thread for TestJob.cmd 2 joined after 1 seconds.
Process for TestJob.cmd 10 finished in 9 seconds.
Output thread for TestJob.cmd 10 joined after 9 seconds

And now in Oddjob we can see the Exec Job completes when the process does:

Parallel Exec Fixed
So this is a story with a happy ending but a niggling loose end. What was the Java bug that caused this?