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.