Manager’s tests fail in Windows - End of Line Characters (Part 1)

It’s Friday, and I finished the card. What now? Since I’ll be going on vacation for some weeks, there is really no point in starting on another important card. I could go home early, but it’s boardgame’s night at Premium Minds, and I like to participate. I ended up playing Le Havre. Hmm, and what about looking into that story about unit tests that don't run in Windows?

I should provide more context. This project consists mainly of two applications. An old application, mostly in Visual Basic 6 (in the process of converting to C#), and a complementary application in Java. For a while, they were developed by two separate teams. The team that developed the Java application did everything in Linux. The other team naturally worked in Windows. Later on, the teams were merged, and they detected that some unit tests of the Java application failed when executed in a Windows system. The card was created in Jira, but the focus shifted to the application in VB6, and it was never corrected. The card came under scrutiny once again after a new person joined the team and noticed this problem.

Back to Friday, I open the project in Eclipse and run the tests. A few minutes later, everything goes green. Why is everything green!? Maybe over time this was eventually fixed. But running the same tests directly in the terminal with Maven, 5 test classes report failures, totaling 15 tests. Oh no, not again!?

We choose one of these tests at random and find that it on its own successfully passes both in Eclipse and in the terminal with Maven. Damn it!

Upon analyzing the failures reported in the Maven Surefire Plugin XML files, we see that they consist of differences in end of line (EOL) characters.

<failure message="expected:<...01Q00030002Em Falta'[]\n> but was:<...01Q00030002Em Falta'[\r]\n>" type="org.junit.ComparisonFailure">

The test returned one carriage return and one line feed (CRLF), which makes sense in a Windows system, but the test expected only one line feed (LF). However, when we execute the test in Eclipse, it returns one LF, and the test passes. Looking at the code, the latter behavior makes sense as this test class extends from AbstractTestBase, which changes the line.separator property to LF.

import java.util.TimeZone;

import org.easymock.EasyMockSupport;
import org.junit.After;
import org.junit.Before;

public abstract class AbstractTestBase extends EasyMockSupport {
	private String lineSeparator;
	private TimeZone timeZone;

	@Before
	public void setLineSeparator() {
		lineSeparator = System.getProperty("line.separator");
		System.setProperty("line.separator", "\n");
	}

	@After
	public void resetLineSeparator() {
		System.setProperty("line.separator", lineSeparator);
	}

	@Before
	public void setTimeZone() {
		timeZone = TimeZone.getDefault();
		TimeZone lisbon = TimeZone.getTimeZone("Europe/Lisbon");
		TimeZone.setDefault(lisbon);
	}

	@After
	public void resetTimeZone() {
		TimeZone.setDefault(timeZone);
	}
}

This class is used by many of the tests but not all of them. I don't like that this class exists, mainly for two reasons:

• It forces tests that extend this class to run in a pseudosimulation of Unix, with the manipulation of EOL, when most of our customers use Windows.
• It is a misuse of inheritance just to be able to reuse code. It doesn't make much sense to say that a unit test has an “is-a” relationship with AbstractTestBase.

A very simplified version of the test under discussion is

public class EOLTest extends AbstractTestBase {

	@Test
	public void testLogging() {
		Logger logger = Logger.getLogger(EOLTest.class);

		ByteArrayOutputStream out = new ByteArrayOutputStream();
		Layout layout = new SimpleLayout();
		Appender appender = new WriterAppender(layout, out);
		logger.addAppender(appender);

		doSomethingImportant();

		assertEquals("WARN - line was not recognized: '00001Q00030002Em Falta'\n", out.toString());
	}

	private void doSomethingImportant() {
		Logger logger = Logger.getLogger(EOLTest.class);

		logger.warn("line was not recognized: '00001Q00030002Em Falta'");
	}
}

The test in question consists of verifying the expected behavior of the logs. At first glance, this is a code smell, but it ends up making sense in this case, as it is a parser from an old protocol with very little documentation, and it is interesting to obtain information on cases where the parser decided to ignore some type of information.

At this point, my theory is that if the test passes on its own both in Eclipse and in Maven and fails in Maven when it runs alongside other tests, then we must have a case where another test must also be controlling the line.separator property, but without cleaning up at the end of the test. Eclipse and Maven run the tests differently, where Eclipse must use one JVM instance per test, while Maven does not, sharing the JVM instance with this other test, which seems to be the  default behavior of the surefire plugin. In fact, by changing the default value of forkMode from once to always, the tests pass. But this masks the problem without discovering its origin.

I searched the project’s code and didn't find any other line.separator changes. I also searched the project's dependencies and found several places where the System.setProperty function was used, but not one was the line.separator property.

Going back to the test, after a debugging session, we can see where the EOL comes from, which is in the SimpleLayout class. This class has a static variable, LINE_SEP, which captures the line.separator value.

public abstract class Layout implements OptionHandler {

  // Note that the line.separator property can be looked up even by
  // applets.
  public final static String LINE_SEP = System.getProperty("line.separator");
  public final static int LINE_SEP_LEN  = LINE_SEP.length();
 
  …
}

If there is another test that also uses SimpleLayout or a similar class, without inheriting from AbstractTestBase, then it is possible for the static variable LINE_SEP to capture the default value of the Windows platform, CRLF. When the EOLTest test is executed, AbstractTestBase tries to control the line.separator but conflicts with LINE_SEP, which previously captured the EOL, and ends up failing the test. Looking at the code, there is in fact another test under these conditions:

public class AnotherEOLTest {

	@Test
	public void testLogging() {
		Logger logger = Logger.getLogger(AnotherEOLTest.class);

		ByteArrayOutputStream out = new ByteArrayOutputStream();
		Layout layout = new SimpleLayout();
		Appender appender = new WriterAppender(layout, out);
		logger.addAppender(appender);

		doSomethingImportant();
		
		assertTrue(out.toString().startsWith("ERROR - Aborting legacy backup"));
		
	}

	private void doSomethingImportant() {
		Logger logger = Logger.getLogger(AnotherEOLTest.class);

		logger.error("Aborting legacy backup'");
	}
}

This may explain why the tests are not isolated, but it still does not explain why the tests run successfully in Eclipse and unsuccessfully in Maven. We can confirm that they are not isolated by running the following application:

import static org.junit.runner.JUnitCore.runClasses;
import org.junit.runner.Result;

public class JunitApplication {

	public static void main(String[] args) {
		Result result = runClasses(AnotherEOLTest.class, EOLTest.class);
		System.out.println(result.wasSuccessful());
	}
}

The result of the execution is false, but if we change the order of the classes, then they run successfully.

So we have an explanation for why the tests fail, but the question as to why they fail in Maven while they pass successfully in Eclipse remains to be answered.

If the order of the tests is important, we have to analyze how each of the tools orders the test classes it will run.

By default, Maven runs the tests in the order of the file system. When we change the order to reversealphabetical, the unit tests executed by Maven pass, confirming once again that the order of execution is important.

But what is Eclipse’s order of execution? I couldn't find any documentation, so I needed to go to the code. Fortunately, since Eclipse 2018-09 (4.9), it is easy to obtain the command that was executed through Run Configuration:

C:\Program Files\Java\jre1.8.0_221\bin\javaw.exe \
 -Dfile.encoding=UTF-8 \
 -classpath ... \
 org.eclipse.jdt.internal.junit.runner.RemoteTestRunner \
 -version 3 \
 -port 1860 \
 -testLoaderClass org.eclipse.jdt.internal.junit4.runner.JUnit4TestLoader \
 -loaderpluginname org.eclipse.jdt.junit4.runtime \
 -testNameFile "F:\tmp\testNames5048619487606373965.txt"

The testNames5048619487606373965.txt file contains the test classes to be executed by Junit. Upon inspecting the file, we see that the order of this file is not alphabetical and is apparently random. Tests in the RemoteTestRunner class are executed in the order of this file.

The contents of this file are created by the JUnitLaunchConfigurationDelegate class. The order seems random due to iteration over a HashSet, manipulated in the evaluateTests method, which does not guarantee order.

Finally, we see the reason why the unit tests of the Java application did not run successfully in Windows with the execution of Maven in the terminal while they ran successfully with the execution of Eclipse.

When executed through Maven, the first test in the order of the file system does not extend AbstractTestBase. Therefore, it does not manipulate the line.separator property. The test uses a SimpleLayout that contains a static variable that is initialized to the value of the line.separator property, which is CRLF, on a Windows platform. When the second test, which extends from AbstractTestBase, is executed, SimpleLayout has already defined its value as the CRLF value.

In turn, when we execute the tests in Eclipse, it searches the existing test classes in the project and saves them in a HashSet, whose order is undefined and not guaranteed when persisted in the file for the testNameFile argument. The first test executed turns out to be one that extends from AbstractTestBase, and when it instantiates a SimpleLayout, its static variable captures the defined value for LF in AbstractTestBase. When we execute a test that does not extend from AbstractTestBase, SimpleLayout has already defined its variable. But in this case, the test was not sensitive to the EOL character, so the tests passed successfully.

Looking at the code, we may also notice that my theory that the tests in Eclipse would be executed in different instances is wrong and that the tests are in fact all in the same JVM.

I mentioned above that I don't like the existence of the AbstractTestBase class. So, what do we do if we really want to control the EOL character? As noted in the aforementioned link: Don’t be lazy, use @Rules:

import org.junit.rules.TestRule;
import org.junit.runner.Description;
import org.junit.runners.model.Statement;

public class EOLRule implements TestRule {

	private String customLineSeparator;

	public EOLRule(String lineSeparator) {
		customLineSeparator = lineSeparator;
	}

	public Statement apply(final Statement base, Description description) {
		return new Statement() {
			@Override
			public void evaluate() throws Throwable {
				String lineSeparator = System.getProperty("line.separator");
				System.setProperty("line.separator", customLineSeparator);
				try {
					base.evaluate();
				} finally {
					System.setProperty("line.separator", lineSeparator);
				}
			}
		};
	}
}

And the EOLTest becomes:

public class EOLTest {

  	@Rule
  	public TestRule rule = new EOLRule("\n");
  	
  	...
}

Nevertheless, even with the EOLRule, the project still displays the same behavior of failing the tests due to the same manipulation of EOL. We can and want to do better than this. There is no reason why we have to force EOL. We can make the test not sensitive to EOL, like the AnotherEOLTest test, or, if that is not an option, absorb this behavior directly in the test:

public class EOLTest {
  	
	@Test
	public void testLogging() {
		Logger logger = Logger.getLogger(EOLTest.class);

		ByteArrayOutputStream out = new ByteArrayOutputStream();
		Layout layout = new SimpleLayout();
		Appender appender = new WriterAppender(layout, out);
		logger.addAppender(appender);

		doSomethingImportant();

		assertEquals("WARN - line was not recognized: '00001Q00030002Em Falta'" + System.getProperty("line.separator"), out.toString());
	}

	private void doSomethingImportant() {
		Logger logger = Logger.getLogger(EOLTest.class);

		logger.warn("line was not recognized: '00001Q00030002Em Falta'");
	}
}

In short:

• By default, Maven runs tests in the same JVM instance
• By default, Maven runs tests in the order of the file system
• Eclipse runs tests in the same JVM instance
• Eclipse runs tests pseudorandomly
• Favor Junit Rules instead of superclasses for common behaviors
• Do not force EOL in tests or place a hardcoded value, but read the line.separator property when necessary.

More attentive readers may have noticed that the AbstractTestBase class not only manipulates EOL but also puts the time zone in the hardcoded value "Europe/Lisbon". When we removed the AbstractTestBase class, new tests began to fail, but that will be the topic for part 2.

__________________
Featured image from:
https://www.flickr.com/photos/dvanzuijlekom/14560514420

SHARE THIS