Thinking in Java, 3rd ed. Revision 4.0

The primary goal of this framework (89) is to verify the output of the examples in the book. You have already seen lines such as

private static Test monitor = new Test();

at the beginning of most classes that contain a main( ) method. The task of the monitor object is to intercept and save a copy of standard output and standard error into a text file. This file is then used to verify the output of an example program by comparing the contents of the file to the expected output.

We start by defining the exceptions that will be thrown by this test system. The general-purpose exception for the library is the base class for the others. Note that it extends RuntimeException so that checked exceptions are not involved:

//: com:bruceeckel:simpletest:SimpleTestException.java
package com.bruceeckel.simpletest;
 
public class SimpleTestException extends RuntimeException {
	public SimpleTestException(String msg) {
		super(msg);
	}
} ///:~

A basic test is to verify that the number of lines sent to the console by the program is the same as the expected number of lines:

//: com:bruceeckel:simpletest:NumOfLinesException.java
package com.bruceeckel.simpletest;
 
public class NumOfLinesException
extends SimpleTestException {
	public NumOfLinesException(int exp, int out) {
		super("Number of lines of output and "
			+ "expected output did not match.\n" +
			"expected: <" + exp + ">\n" +
			"output:   <" + out + "> lines)");
	}
} ///:~

Or, the number of lines might be correct, but one or more lines might not match:

//: com:bruceeckel:simpletest:LineMismatchException.java
package com.bruceeckel.simpletest;
import java.io.PrintStream;
 
public class LineMismatchException
extends SimpleTestException {
	public LineMismatchException(
		int lineNum, String expected, String output) {
		super("line " + lineNum +
			" of output did not match expected output\n" +
			"expected: <" + expected + ">\n" +
			"output:   <" + output + ">");
	}
} ///:~

This test system works by intercepting the console output using the TestStream class to replace the standard console output and console error:

//: com:bruceeckel:simpletest:TestStream.java
// Simple utility for testing program output. Intercepts
// System.out to print both to the console and a buffer.
package com.bruceeckel.simpletest;
import java.io.*;
import java.util.*;
import java.util.regex.*;
 
public class TestStream extends PrintStream {
	protected int numOfLines;
	private PrintStream
		console = System.out,
		err = System.err,
		fout;
	// To store lines sent to System.out or err
	private InputStream stdin;
	private String className;
	public TestStream(String className) {
		super(System.out, true); // Autoflush
		System.setOut(this);
		System.setErr(this);
		stdin = System.in; // Save to restore in dispose()
		// Replace the default version with one that
		// automatically produces input on demand:
		System.setIn(new BufferedInputStream(new InputStream(){
			char[] input = ("test\n").toCharArray();
			int index = 0;
			public int read() {
				return
					(int)input[index = (index + 1) % input.length];
			}
		}));
		this.className = className;
		openOutputFile();
	}
	// public PrintStream getConsole() { return console; }
	public void dispose() {
		System.setOut(console);
		System.setErr(err);
		System.setIn(stdin);
	}
	// This will write over an old Output.txt file:
	public void openOutputFile() {
		try {
			fout = new PrintStream(new FileOutputStream(
				new File(className + "Output.txt")));
		} catch (FileNotFoundException e) {
			throw new RuntimeException(e);
		}
	}
	// Override all possible print/println methods to send
	// intercepted console output to both the console and
	// the Output.txt file:
	public void print(boolean x) {
		console.print(x);
		fout.print(x);
	}
	public void println(boolean x) {
		numOfLines++;
		console.println(x);
		fout.println(x);
	}
	public void print(char x) {
		console.print(x);
		fout.print(x);
	}
	public void println(char x) {
		numOfLines++;
		console.println(x);
		fout.println(x);
	}
	public void print(int x) {
		console.print(x);
		fout.print(x);
	}
	public void println(int x) {
		numOfLines++;
		console.println(x);
		fout.println(x);
	}
	public void print(long x) {
		console.print(x);
		fout.print(x);
	}
	public void println(long x) {
		numOfLines++;
		console.println(x);
		fout.println(x);
	}
	public void print(float x) {
		console.print(x);
		fout.print(x);
	}
	public void println(float x) {
		numOfLines++;
		console.println(x);
		fout.println(x);
	}
	public void print(double x) {
		console.print(x);
		fout.print(x);
	}
	public void println(double x) {
		numOfLines++;
		console.println(x);
		fout.println(x);
	}
	public void print(char[] x) {
		console.print(x);
		fout.print(x);
	}
	public void println(char[] x) {
		numOfLines++;
		console.println(x);
		fout.println(x);
	}
	public void print(String x) {
		console.print(x);
		fout.print(x);
	}
	public void println(String x) {
		numOfLines++;
		console.println(x);
		fout.println(x);
	}
	public void print(Object x) {
		console.print(x);
		fout.print(x);
	}
	public void println(Object x) {
		numOfLines++;
		console.println(x);
		fout.println(x);
	}
	public void println() {
		if(false) console.print("println");
		numOfLines++;
		console.println();
		fout.println();
	}
	public void
	write(byte[] buffer, int offset, int length) {
		console.write(buffer, offset, length);
		fout.write(buffer, offset, length);
	}
	public void write(int b) {
		console.write(b);
		fout.write(b);
	}
} ///:~

The constructor for TestStream, after calling the constructor for the base class, first saves references to standard output and standard error, and then redirects both streams to the TestStream object. The static methods setOut( ) and setErr( ) both take a PrintStream argument. System.out and System.err references are unplugged from their normal object and instead are plugged into the TestStream object, so TestStream must also be a PrintStream (or equivalently, something inherited from PrintStream). The original standard output PrintStream reference is captured in the console reference inside TestStream, and every time console output is intercepted, it is sent to the original console as well as to an output file. The dispose( ) method is used to set standard I/O references back to their original objects when TestStream is finished with them.

For automatic testing of examples that require user input from the console, the constructor redirects calls to standard input. The current standard input is stored in a reference so that dispose( ) can restore it to its original state. Using System.setIn( ), an anonymous inner class is set to handle any requests for input by the program under test. The read( ) method of this inner class produces the letters "test" followed by a newline.

TestStream overrides a variety of PrintStream print( ) and println( ) methods for each type. Each of these methods writes both to the "standard" output and to an output file. The expect( ) method can then be used to test whether output produced by a program matches the expected output provided as argument to expect( ).

These tools are used in the Test class:

//: com:bruceeckel:simpletest:Test.java
// Simple utility for testing program output. Intercepts
// System.out to print both to the console and a buffer.
package com.bruceeckel.simpletest;
import java.io.*;
import java.util.*;
import java.util.regex.*;
 
public class Test {
	// Bit-shifted so they can be added together:
	public static final int
		EXACT = 1 << 0, // Lines must match exactly
		AT_LEAST = 1 << 1, // Must be at least these lines
		IGNORE_ORDER = 1 << 2, // Ignore line order
		WAIT = 1 << 3; // Delay until all lines are output
	private String className;
	private TestStream testStream;
	public Test() {
		// Discover the name of the class this
		// object was created within:
		className =
			new Throwable().getStackTrace()[1].getClassName();
		testStream = new TestStream(className);
	}
	public static List fileToList(String fname) {
		ArrayList list = new ArrayList();
		try {
			BufferedReader in =
				new BufferedReader(new FileReader(fname));
			try {
				String line;
				while((line = in.readLine()) != null) {
					if(fname.endsWith(".txt"))
						list.add(line);
					else
						list.add(new TestExpression(line));
				}
			} finally {
				in.close();
			}
		} catch (IOException e) {
			throw new RuntimeException(e);
		}
		return list;
	}
	public static List arrayToList(Object[] array) {
		List l = new ArrayList();
		for(int i = 0; i < array.length; i++) {
			if(array[i] instanceof TestExpression) {
				TestExpression re = (TestExpression)array[i];
				for(int j = 0; j < re.getNumber(); j++)
					l.add(re);
				} else {
					l.add(new TestExpression(array[i].toString()));
			}
		}
		return l;
	}
	public void expect(Object[] exp, int flags) {
		if((flags & WAIT) != 0)
			while(testStream.numOfLines < exp.length) {
				try {
					Thread.sleep(1000);
				} catch (InterruptedException e) {
					throw new RuntimeException(e);
				}
			}
		List output = fileToList(className + "Output.txt");
		if((flags & IGNORE_ORDER) == IGNORE_ORDER)
			OutputVerifier.verifyIgnoreOrder(output, exp);
		else if((flags & AT_LEAST) == AT_LEAST)
			OutputVerifier.verifyAtLeast(output,
				arrayToList(exp));
		else
			OutputVerifier.verify(output, arrayToList(exp));
		// Clean up the output file - see c06:Detergent.java
		testStream.openOutputFile();
	}
	public void expect(Object[] expected) {
		expect(expected, EXACT);
	}
	public void expect(Object[] expectFirst,
		String fname, int flags) {
		List expected = fileToList(fname);
		for(int i = 0; i < expectFirst.length; i++)
			expected.add(i, expectFirst[i]);
			expect(expected.toArray(), flags);
	}
	public void expect(Object[] expectFirst, String fname) {
		expect(expectFirst, fname, EXACT);
	}
	public void expect(String fname) {
    	expect(new Object[] {}, fname, EXACT);
	}
} ///:~

There are several overloaded versions of expect( ) provided for convenience (so the client programmer can, for example, provide the name of the file containing the expected output instead of an array of expected output lines). These overloaded methods all call the main expect( ) method, which takes as arguments an array of Objects containing expected output lines and an int containing various flags. Flags are implemented using bit shifting, with each bit corresponding to a particular flag as defined at the beginning of Test.java.

The expect( ) method first inspects the flags argument to see if it should delay processing to allow a slow program to catch up. It then calls a static method fileToList( ), which converts the contents of the output file produced by a program into a List. The fileToList( ) method also wraps each String object in an OutputLine object; the reason for this will become clear. Finally, the expect( ) method calls the appropriate verify( ) method based on the flags argument.

There are three verifiers: verify( ), verifyIgnoreOrder( ), and verifyAtLeast( ), corresponding to EXACT, IGNORE_ORDER, and AT_LEAST modes, respectively:

//: com:bruceeckel:simpletest:OutputVerifier.java
package com.bruceeckel.simpletest;
import java.util.*;
import java.io.PrintStream;
 
public class OutputVerifier {
	private static void verifyLength(
		int output, int expected, int compare) {
		if((compare == Test.EXACT && expected != output)
			|| (compare == Test.AT_LEAST && output < expected))
				throw new NumOfLinesException(expected, output);
	}
	public static void verify(List output, List expected) {
	verifyLength(output.size(),expected.size(),Test.EXACT);
	if(!expected.equals(output)) {
		//find the line of mismatch
		ListIterator it1 = expected.listIterator();
		ListIterator it2 = output.listIterator();
		while(it1.hasNext()
			&& it2.hasNext()
			&& it1.next().equals(it2.next()));
				throw new LineMismatchException(
					it1.nextIndex(), it1.previous().toString(),
					it2.previous().toString());
		}
	}
	public static void
	verifyIgnoreOrder(List output, Object[] expected) {
		verifyLength(expected.length,output.size(),Test.EXACT);
		if(!(expected instanceof String[]))
			throw new RuntimeException(
				"IGNORE_ORDER only works with String objects");
		String[] out = new String[output.size()];
		Iterator it = output.iterator();
		for(int i = 0; i < out.length; i++)
			out[i] = it.next().toString();
		Arrays.sort(out);
		Arrays.sort(expected);
		int i =0;
		if(!Arrays.equals(expected, out)) {
			while(expected[i].equals(out[i])) {i++;}
			throw new SimpleTestException(
				((String) out[i]).compareTo(expected[i]) < 0
					? "output: <" + out[i] + ">"
					: "expected: <" + expected[i] + ">");
		}
	}
	public static void
	verifyAtLeast(List output, List expected) {
		verifyLength(output.size(), expected.size(),
			Test.AT_LEAST);
		if(!output.containsAll(expected)) {
			ListIterator it = expected.listIterator();
			while(output.contains(it.next())) {}
			throw new SimpleTestException(
				"expected: <" + it.previous().toString() + ">");
		}
	}
} ///:~

The "verify" methods test whether the output produced by a program matches the expected output as specified by the particular mode. If this is not the case, the "verify" methods raise an exception that aborts the build process.

Each of the "verify" methods uses verifyLength( ) to test the number of lines of output. EXACT mode requires that both output and expected output arrays be the same size, and that each output line is equal to the corresponding line in the expected output array. IGNORE_ORDER still requires that both arrays be the same size, but the actual order of appearance of the lines is disregarded (the two output arrays must be permutations of one another). IGNORE_ORDER mode is used to test threading examples where, due to non-deterministic scheduling of threads by the JVM, it is possible that the sequence of output lines produced by a program cannot be predicted. AT_LEAST mode does not require the two arrays to be the same size, but each line of expected output must be contained in the actual output produced by a program, regardless of order. This feature is particularly useful for testing program examples that contain output lines that may or may not be printed, as is the case with most of the examples dealing with garbage collection. Notice that the three modes are canonical; that is, if a test passes in IGNORE_ORDER mode, then it will also pass in AT_LEAST mode, and if it passes in EXACT mode, it will also pass in the other two modes.

Notice how simple the implementation of the "verify" methods is. verify( ), for example, simply calls the equals( ) method provided by the List class, and verifyAtLeast( ) calls List.containsAll( ). Remember that the two output Lists can contain both OutputLine or RegularExpression objects. The reason for wrapping the simple String object in OutputLines should now become clear; this approach allows us to override the equals( ) method, which is necessary in order to take advantage of the Java Collections API.

Objects in the expect( ) array can be either Strings or TestExpressions, which can encapsulate a regular expression (described in Chapter 12), which is useful for testing examples that produce random output. The TestExpression class encapsulates a String representing a particular regular expression.

//: com:bruceeckel:simpletest:TestExpression.java
// Regular expression for testing program output lines
package com.bruceeckel.simpletest;
import java.util.regex.*;
 
public class TestExpression implements Comparable {
	private Pattern p;
	private String expression;
	private boolean isRegEx;
	// Default to only one instance of this expression:
	private int duplicates = 1;
	public TestExpression(String s) {
		this.expression = s;
		if(expression.startsWith("%% ")) {
			this.isRegEx = true;
			expression = expression.substring(3);
			this.p = Pattern.compile(expression);
		}
	}
	// For duplicate instances:
	public TestExpression(String s, int duplicates) {
		this(s);
		this.duplicates = duplicates;
	}
	public String toString() {
		if(isRegEx) return p.pattern();
		return expression;
	}
	public boolean equals(Object obj) {
		if(this == obj) return true;
		if(isRegEx) return (compareTo(obj) == 0);
		return expression.equals(obj.toString());
	}
	public int compareTo(Object obj) {
		if((isRegEx) && (p.matcher(obj.toString()).matches()))
			return 0;
		return expression.compareTo(obj.toString());
	}
	public int getNumber() {  return duplicates; }
	public String getExpression() { return expression;}
	public boolean isRegEx() { return isRegEx; }
} ///:~

TestExpression can distinguish regular expression patterns from String literals. The second constructor allows multiple identical expression lines to be wrapped in a single object for convenience.

This test system has been reasonably useful, and the exercise of creating it and putting it into use has been invaluable. However, in the end I'm not that pleased with it and have ideas that will probably be implemented in the next edition of the book (or possibly sooner).

Although the testing framework just described allows you to verify program output simply and easily, in some cases you may want to perform more extensive functionality testing on a program. JUnit, available at www.junit.org, is a quickly emerging standard for writing repeatable tests for Java programs, and provides both simple and complex testing.

The original JUnit was presumably based on JDK 1.0 and thus could not make use of Java's reflection facilities. As a result, writing unit tests with the old JUnit was a rather busy and wordy activity, and I found the design to be unpleasant. Because of this, I wrote my own unit testing framework for Java, (90) going to the other extreme and "doing the simplest thing that could possibly work." (91) Since then, JUnit has been modified and uses reflection to greatly simplify the process of writing unit test code. Although you still have the option of writing code the "old" way with test suites and all the other complex details, I believe that in the great majority of cases you can follow the simple approach shown here (and make your life more pleasant).

In the simplest approach to using JUnit, you put all your tests in a subclass of TestCase. Each test must be public, take no arguments, return void, and have a method name beginning with the word "test." Junit's reflection will identify these methods as individual tests and set up and run them one at a time, taking measures to avoid side effects between the tests.

Traditionally, the setUp( ) method creates and initializes a common set of objects that will be used in all the tests; however, you can also just put all such initialization in the constructor for the test class. JUnit creates an object for each test to ensure there will be no side effects between test runs. However, all the objects for all the tests are created at once (rather than creating the object right before the test), so the only difference between using setUp( ) and the constructor is that setUp( ) is called directly before the test. In most situations this will not be an issue, and you can use the constructor approach for simplicity.

If you need to perform any cleanup after each test (if you modify any statics that need to be restored, open files that need to be closed, open network connections, etc.), you write a tearDown( ) method. This is also optional.

The following example uses this simple approach to create JUnit tests that exercise the standard Java ArrayList class. To trace how JUnit creates and cleans up its test objects, CountedList is inherited from ArrayList and tracking information is added:

//: c15:JUnitDemo.java
// Simple use of JUnit to test ArrayList
// {Depends: junit.jar}
import java.util.*;
import junit.framework.*;
 
// So we can see the list objects being created,
// and keep track of when they are cleaned up:
class CountedList extends ArrayList {
	private static int counter = 0;
	private int id = counter++;
	public CountedList() {
		System.out.println("CountedList #" + id);
	}
	public int getId() { return id; }
}
 
public class JUnitDemo extends TestCase {
	private static com.bruceeckel.simpletest.Test monitor =
		new com.bruceeckel.simpletest.Test();
	private CountedList list = new CountedList();
	// You can use the constructor instead of setUp():
	public JUnitDemo(String name) {
		super(name);
		for(int i = 0; i < 3; i++)
			list.add("" + i);
	}
	// Thus, setUp() is optional, but is run right
	// before the test:
	protected void setUp() {
		System.out.println("Set up for " + list.getId());
	}
	// tearDown() is also optional, and is called after
	// each test. setUp() and tearDown() can be either
	// protected or public:
	public void tearDown() {
		System.out.println("Tearing down " + list.getId());
	}
	// All tests have method names beginning with "test":
	public void testInsert() {
		System.out.println("Running testInsert()");
		assertEquals(list.size(), 3);
		list.add(1, "Insert");
		assertEquals(list.size(), 4);
		assertEquals(list.get(1), "Insert");
	}
	public void testReplace() {
		System.out.println("Running testReplace()");
		assertEquals(list.size(), 3);
		list.set(1, "Replace");
		assertEquals(list.size(), 3);
		assertEquals(list.get(1), "Replace");
	}
	// A "helper" method to reduce code duplication. As long
	// as the name doesn't start with "test," it will not
	// be automatically executed by JUnit.
	private void compare(ArrayList lst, String[] strs) {
		Object[] array = lst.toArray();
		assertTrue("Arrays not the same length",
			array.length == strs.length);
		for(int i = 0; i < array.length; i++)
			assertEquals(strs[i], (String)array[i]);
	}
	public void testOrder() {
		System.out.println("Running testOrder()");
		compare(list, new String[] { "0", "1", "2" });
	}
	public void testRemove() {
		System.out.println("Running testRemove()");
		assertEquals(list.size(), 3);
		list.remove(1);
		assertEquals(list.size(), 2);
		compare(list, new String[] { "0", "2" });
	}
	public void testAddAll() {
		System.out.println("Running testAddAll()");
		list.addAll(Arrays.asList(new Object[] {
			"An", "African", "Swallow"}));
		assertEquals(list.size(), 6);
		compare(list, new String[] { "0", "1", "2",
			"An", "African", "Swallow" });
	}
	public static void main(String[] args) {
		// Invoke JUnit on the class:
		junit.textui.TestRunner.run(JUnitDemo.class);
		monitor.expect(new String[] {
			"CountedList #0",
			"CountedList #1",
			"CountedList #2",
			"CountedList #3",
			"CountedList #4",
			// '.' indicates the beginning of each test:
			".Set up for 0",
			"Running testInsert()",
			"Tearing down 0",
			".Set up for 1",
			"Running testReplace()",
			"Tearing down 1",
			".Set up for 2",
			"Running testOrder()",
			"Tearing down 2",
			".Set up for 3",
			"Running testRemove()",
			"Tearing down 3",
			".Set up for 4",
			"Running testAddAll()",
			"Tearing down 4",
			"",
			"%% Time: .*",
			"",
			"OK (5 tests)",
			"",
		});
	}
} ///:~

To set up unit testing, you must only import junit.framework.* and extend TestCase, as JUnitDemo does. In addition, you must create a constructor that takes a String argument and passes it to its super constructor.

For each test, a new JUnitDemo object will be created, and thus all the non-static members will also be created. This means a new CountedList object (list)will be created and initialized for each test, since it is a field of JUnitDemo. In addition, the constructor will be called for each test, so list will be initialized with the strings "0", "1", and "2" before each test is run.

To observe the behavior of setUp( ) and tearDown( ), these methods are created to display information about the test that's being initialized or cleaned up. Note that the base-class methods are protected, so the overridden methods may be either protected or public.

testInsert( ) and testReplace( ) demonstrate typical test methods, since they follow the required signature and naming convention. JUnit discovers these methods using reflection and runs each one as a test. Inside the methods, you perform any desired operations and use JUnit assertion methods (which all start with the name "assert") to verify the correctness of your tests (the full range of "assert" statements can be found in the JUnit javadocs for junit.framework.Assert). If the assertion fails, the expression and values that caused the failure will be displayed. This is usually enough, but you can also use the overloaded version of each JUnit assertion statement and include a String that will be printed if the assertion fails.

The assertion statements are not required; you can also just run the test without assertions and consider it a success if no exceptions are thrown.

The compare( ) method is an example of a "helper" method that is not executed by JUnit but instead is used by other tests in the class. As long as the method name doesn't begin with "test," JUnit doesn't run it or expect it to have a particular signature. Here, compare( ) is private to emphasize that it is only used within the test class, but it could also be public. The remaining test methods eliminate duplicate code by refactoring it into the compare( ) method.

To execute the JUnit tests, the static method TestRunner.run( ) is invoked in main( ). This method is handed the class that contains the collection of tests, and it automatically sets up and runs all the tests. From the expect( ) output, you can see that all the objects needed to run all the tests are created first, in a batch-this is where the construction happens. (92) Before each test, the setUp( ) method is called. Then the test is run, followed by the tearDown( ) method. JUnit demarcates each test with a '.'.

Although you can probably survive easily by only using the simplest approach to JUnit as shown in the preceding example, JUnit was originally designed with a plethora of complicated structures. If you are curious, you can easily learn more about them, because the JUnit download from www.JUnit.org comes with documentation and tutorials.

Since you can simulate the effect of assertions using other programming constructs, it can be argued that the whole point of adding assertions to Java is that they are easy to write. Assertion statements come in two forms:

assert boolean-expression;
assert boolean-expression: information-expression;

Both of these statements say "I assert that the boolean-expression will produce a true value." If this is not the case, the assertion will produce an AssertionError exception. This is a Throwable subclass, and as such doesn't require an exception specification.

Unfortunately, the first form of assertion does not produce any information containing the boolean-expression in the exception produced by a failed assertion (in contrast with most other languages' assertion mechanisms). Here's an example showing the use of the first form:

//: c15:Assert1.java
// Non-informative style of assert
// Compile with: javac -source 1.4 Assert1.java
// {JVMArgs: -ea} // Must run with -ea
// {ThrowsException}
 
public class Assert1 {
	public static void main(String[] args) {
		assert false;
	}
} ///:~

Assertions are turned off in JDK 1.4 by default (this is annoying, but the designers managed to convince themselves it was a good idea). To prevent compile-time errors, you must compile with the flag:

-source 1.4

If you don't use this flag, you'll get a chatty message saying that assert is a keyword in JDK 1.4 and cannot be used as an identifier anymore.

If you just run the program the way you normally do, without any special assertion flags, nothing will happen. You must enable assertions when you run the program. The easiest way to do this is with the -ea flag, but you can also spell it out: -enableassertions. This will run the program and execute any assertion statements, so you'll get:

Exception in thread "main" java.lang.AssertionError
	at Assert1.main(Assert1.java:8)

You can see that the output doesn't contain much in the way of useful information. On the other hand, if you use the information-expression, you'll produce a helpful message when the assertion fails.

To use the second form, you provide an information-expression that will be displayed as part of the exception stack trace. This information-expression can produce any data type at all. However, the most useful information-expression will typically be a string with text that is useful to the programmer. Here's an example:

//: c15:Assert2.java
// Assert with an informative message
// {JVMArgs: -ea}
// {ThrowsException}
 
public class Assert2 {
	public static void main(String[] args) {
		assert false: "Here's a message saying what happened";
	}
} ///:~

Now the output is:

Exception in thread "main" java.lang.AssertionError: Here's a message saying what happened
	at Assert2.main(Assert2.java:6)

Although what you see here is just a simple String object, the information-expression can produce any kind of object, so you will typically construct a more complex string containing, for example, the value(s) of objects that were involved with the failed assertion.

Because the only way to see useful information from a failed assertion is to use the information-expression, that is the form that is always used in this book, and the first form will be considered to be a poor choice.

You can also decide to turn assertions on and off based on class name or package name (that is, you can enable or disable assertions in an entire package). You can find the details in the JDK 1.4 documentation on assertions. This can be useful if you have a large project instrumented with assertions and you want to turn some of them off. However, logging or debugging (both described later in this chapter) are probably better tools for capturing that kind of information. This book will just turn on all assertions when necessary, so we will ignore the fine-grained control of assertions.

There's one other way you can control assertions: programmatically, by hooking into the ClassLoader object. JDK 1.4 added several new methods to ClassLoader that allow the dynamic enabling and disabling of assertions, including setDefaultAssertionStatus( ), which sets the assertion status for all the classes loaded afterward. So you might think you could almost silently turn on all assertions like this:

//: c15:LoaderAssertions.java
// Using the class loader to enable assertions
// Compile with: javac -source 1.4 LoaderAssertions.java
// {ThrowsException}
 
public class LoaderAssertions {
	public static void main(String[] args) {
		ClassLoader.getSystemClassLoader()
			.setDefaultAssertionStatus(true);
		new Loaded().go();
	}
}
 
class Loaded {
	public void go() {
		assert false: "Loaded.go()";
	}
} ///:~

Although this does eliminate the need to use the -ea flag on the command line when the Java program is run, it's not a complete solution because you must still compile everything with the -source 1.4 flag. It may be just as straightforward to enable assertions using command-line arguments; when delivering a standalone product, you probably have to set up an execution script for the user to start the program anyway, in order to configure other startup parameters.

It does make sense, however, to decide that you want to require assertions to be enabled when the program is run. You can accomplish this with the following static clause, placed in the main class of your system:

static {
	boolean assertionsEnabled = false;
	// Note intentional side effect of assignment:
	assert assertionsEnabled = true;
	if (!assertionsEnabled)
		throw new RuntimeException("Assertions disabled");
}

If assertions are enabled, then the assert statement will be executed and assertionsEnabled will be set to true. The assertion will never fail, because the return value of the assignment is the assigned value. If assertions are not enabled, the assert statement will not be executed and assertionsEnabled will remain false, resulting in the exception.

Design by Contract (DBC) is a concept developed by Bertrand Meyer, creator of the Eiffel programming language, to help in the creation of robust programs by guaranteeing that objects follow certain rules that cannot be verified by compile-time type checking. (93) These rules are determined by the nature of the problem that is being solved, which is outside the scope of what the compiler can know about and test.

Although assertions do not directly implement DBC (as does the Eiffel language), they can be used to create an informal style of DBC programming.

The fundamental idea of DBC is that a clearly-specified contract exists between the supplier of a service and the consumer or client of that service. In object-oriented programming, services are usually supplied by objects, and the boundary of the object-the division between the supplier and consumer-is the interface of the object's class. When clients call a particular public method, they are expecting certain behavior from that call: a state change in the object, and a predictable return value. Meyer's thesis is that:

• This behavior can be clearly specified, as if it were a contract.
• This behavior can be guaranteed by implementing certain run-time checks, which he calls preconditions, postconditions and invariants.

Whether or not you agree that point 1 is always true, it does appear to be true for enough situations to make DBC an interesting approach. (I believe that, like any solution, there are boundaries to its usefulness. But if you know these boundaries, you know when to try to apply it.) In particular, a very valuable part of the design process is the expression of the DBC constraints for a particular class; if you are unable to specify the constraints, you probably don't know enough about what you're trying to build.

15-2-2-1. Check instructions▲

assert Thread.holdsLock(this); // lock-status assertion

15-2-2-2. Preconditions▲

15-2-2-3. Postconditions▲

15-2-2-4. Invariants▲

assert invariant();

15-2-2-5. Relaxing DBC▲

The following example demonstrates the potency of combining concepts from Design by Contract with unit testing. It shows a small first-in, first-out (FIFO) queue class that is implemented as a "circular" array-that is, an array used in a circular fashion. When the end of the array is reached, the class wraps back around to the beginning.

We can make a number of contractual definitions for this queue:

• Precondition (for a put( )): Null elements are not allowed to be added to the queue.
• Precondition (for a put( )): It is illegal to put elements into a full queue.
• Precondition (for a get( )): It is illegal to try to get elements from an empty queue.
• Postcondition (for a get( )): Null elements cannot be produced from the array.
• Invariant: The region in the array that contains objects cannot contain any null elements.
• Invariant: The region in the array that doesn't contain objects must have only null values.

Here is one way you could implement these rules, using explicit method calls for each type of DBC element:

//: c15:Queue.java
// Demonstration of Design by Contract (DBC) combined
// with white-box unit testing.
// {Depends: junit.jar}
import junit.framework.*;
import java.util.*;
 
public class Queue {
	private Object[] data;
	private int
		in = 0, // Next available storage space
		out = 0; // Next gettable object
	// Has it wrapped around the circular queue?
	private boolean wrapped = false;
	public static class
	QueueException extends RuntimeException {
		public QueueException(String why) { super(why); }
	}
	public Queue(int size) {
		data = new Object[size];
		assert invariant(); // Must be true after construction
	}
	public boolean empty() {
		return !wrapped && in == out;
	}
	public boolean full() {
		return wrapped && in == out;
	}
	public void put(Object item) {
		precondition(item != null, "put() null item");
		precondition(!full(), "put() into full Queue");
		assert invariant();
		data[in++] = item;
		if(in >= data.length) {
			in = 0;
			wrapped = true;
		}
		assert invariant();
	}
	public Object get() {
		precondition(!empty(), "get() from empty Queue");
		assert invariant();
		Object returnVal = data[out];
		data[out] = null;
		out++;
		if(out >= data.length) {
			out = 0;
			wrapped = false;
		}
		assert postcondition(
			returnVal != null, "Null item in Queue");
		assert invariant();
		return returnVal;
	}
	// Design-by-contract support methods:
	private static void
	precondition(boolean cond, String msg) {
		if(!cond) throw new QueueException(msg);
	}
	private static boolean
	postcondition(boolean cond, String msg) {
		if(!cond) throw new QueueException(msg);
		return true;
	}
	private boolean invariant() {
		// Guarantee that no null values are in the
		// region of 'data' that holds objects:
		for(int i = out; i != in; i = (i + 1) % data.length)
			if(data[i] == null)
				throw new QueueException("null in queue");
		// Guarantee that only null values are outside the
		// region of 'data' that holds objects:
		if(full()) return true;
		for(int i = in; i != out; i = (i + 1) % data.length)
			if(data[i] != null)
				throw new QueueException(
					"non-null outside of queue range: " + dump());
		return true;
	}
	private String dump() {
		return "in = " + in +
			", out = " + out +
			", full() = " + full() +
			", empty() = " + empty() +
			", queue = " + Arrays.asList(data);
	}
	// JUnit testing.
	// As an inner class, this has access to privates:
	public static class WhiteBoxTest extends TestCase {
		private Queue queue = new Queue(10);
		private int i = 0;
		public WhiteBoxTest(String name) {
			super(name);
			while(i < 5) // Preload with some data
			queue.put("" + i++);
		}
		// Support methods:
		private void showFullness() {
			assertTrue(queue.full());
			assertFalse(queue.empty());
			// Dump is private, white-box testing allows access:
			System.out.println(queue.dump());
		}
		private void showEmptiness() {
			assertFalse(queue.full());
			assertTrue(queue.empty());
			System.out.println(queue.dump());
		}
		public void testFull() {
			System.out.println("testFull");
			System.out.println(queue.dump());
			System.out.println(queue.get());
			System.out.println(queue.get());
			while(!queue.full())
				queue.put("" + i++);
			String msg = "";
			try {
				queue.put("");
			} catch(QueueException e) {
				msg = e.getMessage();
				System.out.println(msg);
			}
			assertEquals(msg, "put() into full Queue");
			showFullness();
		}
		public void testEmpty() {
			System.out.println("testEmpty");
			while(!queue.empty())
				System.out.println(queue.get());
			String msg = "";
			try {
				queue.get();
			} catch(QueueException e) {
				msg = e.getMessage();
				System.out.println(msg);
			}
			assertEquals(msg, "get() from empty Queue");
			showEmptiness();
		}
		public void testNullPut() {
			System.out.println("testNullPut");
			String msg = "";
			try {
				queue.put(null);
			} catch(QueueException e) {
				msg = e.getMessage();
				System.out.println(msg);
			}
			assertEquals(msg, "put() null item");
		}
		public void testCircularity() {
			System.out.println("testCircularity");
			while(!queue.full())
				queue.put("" + i++);
			showFullness();
			// White-box testing accesses private field:
			assertTrue(queue.wrapped);
			while(!queue.empty())
				System.out.println(queue.get());
			showEmptiness();
			while(!queue.full())
				queue.put("" + i++);
			showFullness();
			while(!queue.empty())
				System.out.println(queue.get());
			showEmptiness();
		}
	}
	public static void main(String[] args) {
		junit.textui.TestRunner.run(Queue.WhiteBoxTest.class);
	}
} ///:~

The in counter indicates the place in the array where the next object will go into, and the out counter indicates where the next object will come from. The wrapped flag shows that in has gone "around the circle" and is now coming up from behind out. When in and out coincide, the queue is empty (if wrapped is false) or full (if wrapped is true).

You can see that the put( ) and get( ) methods call the methods precondition( ), postcondition( ), and invariant( ), which are private methods defined further down in the class. precondition( ) and postcondition( ) are helper methods designed to clarify the code. Note that precondition( ) returns void, because it is not used with assert. As previously noted, you'll generally want to keep preconditions in your code; however, by wrapping them in a precondition( ) method call, you have better options if you are reduced to the dire move of turning them off.

postcondition( ) and invariant( ) return a Boolean value so that they can be used in assert statements. Then, if assertions are disabled for performance reasons, there will be no method calls at all.

invariant( ) performs internal validity checks on the object. You can see that this is an expensive operation to do at both the beginning and ending of every method call, as Meyer suggests. However, it's very valuable to have this clearly represented in code, and it helped me get the implementation to be correct. In addition, if you make any changes to the implementation, the invariant( ) will ensure that you haven't broken the code. But you can see that it would be fairly trivial to move the invariant tests from the method calls into the unit test code. If your unit tests are reasonably thorough, you can have a reasonable level of confidence that the invariants will be respected.

Notice that the dump( ) helper method returns a string containing all the data rather than printing the data directly. This approach allows many more options as to how the information can be used.

The TestCase subclass WhiteBoxTest is created as an inner class so that it has access to the private elements of Queue and is thus able to validate the underlying implementation, not just the behavior of the class as in a white-box test. The constructor adds some data so that the Queue is partially full for each test. The support methods showFullness( ) and showEmptiness( ) are meant to be called to verify that the Queue is full or empty, respectively. Each of the four test methods ensures that a different aspect of the Queue operation functions correctly.

Note that by combining DBC with unit testing, you not only get the best of both worlds, but you also have a migration path-you can move DBC tests to unit tests rather than simply disabling them, so you still have some level of testing.

I came to realize that for a system to be built in a robust and reliable fashion, I needed to automate everything that goes into the build process. This requires some concentration up front, just like writing a program requires concentration, but the payoff is that you solve the problems once, and you rely on your build configuration to take care of the details from then on. It's a variation of the fundamental programming principle of abstraction: We raise ourselves up from the grinding details by hiding those details inside a process and giving that process a name. For many years, the name of that process was make.

The make utility appeared along with C as a tool to create the Unix operating system. make's primary function is to compare the date of two files and to perform some operation that will bring those two files up-to-date with each other. The relationships between all the files in your projects and the rules necessary to bring them up-to-date (the rule is usually running the C/C++ compiler on a source file) are contained in a makefile. The programmer creates a makefile containing the description of how to build the system. When you want to bring the system up-to-date, you simply type make at the command line. To this day, installing Unix/Linux programs consists of unpacking them and typing make commands.

The concept of make is clearly a good idea, and this idea proliferated to produce many versions of make. C and C++ compiler vendors typically included their own variation of make along with their compiler-these variations often took liberties with what people considered to be the standard makefile rules, so the resulting makefiles wouldn't run with each other. The problem was finally solved (as has often been the case) by a make that was, and still is, superior to all the other makes, and is also free, so there's no resistance to using it: GNU make. (94) This tool has a significantly better feature set than the other versions of make and is available on all platforms.

In the previous two editions of Thinking in Java, I used makefiles to build all the code in the book's source-code tree. I automatically generated these makefiles-one in each directory, and a master makefile in the root directory that would call the rest-using a tool that I originally wrote in C++ (in about 2 weeks) for Thinking in C++,and later rewrote in Python (in about half a day) called MakeBuilder.py. (95) It worked for both Windows and Linux/Unix, but I had to write extra code to make this happen, and I never tried it on the Macintosh. Therein lies the first problem with make: You can get it to work on multiple platforms, but it's not inherently cross-platform. So for a language that's supposed to be "write once, run anywhere" (that is, Java), you can spend a lot of effort getting the same behavior in the build system if you use make.

The rest of the problems with make can probably be summarized by saying that it is like a lot of tools developed for Unix; the person creating the tool couldn't resist the temptation to create their own language syntax, and as a result, Unix is filled with tools that are all remarkably different, and equally incomprehensible. That is to say, the make syntax is quite difficult to understand in its entirety-I've been learning it for years-and has lots of annoying things like its insistence on tabs instead of spaces. (96)

All that said, note that I still find GNU make indispensable for many of the projects I create.

All of these issues with make irritated a Java programmer named James Duncan Davidson enough to cause him to create Ant as an open-source tool that migrated to the Apache project at http://jakarta.apache.org/ant. This site contains the full download including the Antexecutable and documentation. Ant has grown and improved until it is now generally accepted as the defacto standard build tool for Java projects.

To make Ant cross-platform, the format for the project description files is XML (covered in Thinking in Enterprise Java). Instead of a makefile, you create a buildfile, which is named by default build.xml (this allows you to just say 'ant' on the command line. If you name your buildfile something else, you have to specify that name with a command-line flag).

The only rigid requirement for your buildfile is that it be a valid XML file. Ant compensates for platform-specific issues like end-of-line characters and directory path separators. You can use tabs or spaces in the buildfile as you prefer. In addition, the syntax and tag names used in buildfiles result in readable, understandable (and thus, maintainable) code.

On top of all this, Ant is designed to be extensible, with a standard interface that allows you to write your own tasks if the ones that come with Ant aren't enough (however, they usually are, and the arsenal is regularly expanding).

Unlike make, the learning curve for Ant is reasonably gentle. You don't need to know much in order to create a buildfile that compiles Java code in a directory. Here's a very basic build.xml file, for example, from Chapter 2 of this book:

<?xml version="1.0"?>
 
<project name="Thinking in Java (c02)" 
	default="c02.run" basedir=".">
	<!-- build all classes in this directory -->
	<target name="c02.build">
		<javac
			srcdir="${basedir}"
			classpath="${basedir}/.."
			source="1.4"
		/>
	</target>
 
	<!-- run all classes in this directory -->
	<target name="c02.run" depends="c02.build">
		<antcall target="HelloDate.run"/>
	</target>
 
	<target name="HelloDate.run">
		<java
			taskname="HelloDate"
			classname="HelloDate"
			classpath="${basedir};${basedir}/.."
			fork="true"
			failonerror="true"
		/>
	</target>
 
	<!-- delete all class files -->
	<target name="clean">
		<delete>
			<fileset dir="${basedir}" includes="**/*.class"/>
			<fileset dir="${basedir}" includes="**/*Output.txt"/>
		</delete>
		<echo message="clean successful"/>
	</target>
 
</project>

The first line states that this file conforms to version 1.0 of XML. XML looks a lot like HTML (notice the comment syntax is identical), except that you can make up your own tag names and the format must strictly conform to XML rules. For example, an opening tag like <project must either end within the tag at its closing angle brace with a slash (/>) or have a matching closing tag like you see at the end of the file (</project>). Within a tag you can have attributes, but the attribute values must be surrounded in quotes. XML allows free formatting, but indentation like you see here is typical.

Each buildfile can manage a single project described by its <project> tag. The project has an optional name attribute that is used when displaying information about the build. The default attribute is required and refers to the target that is built when you just type ant at the command line without giving a specific target name. The directory reference basedir can be used in other places in the buildfile.

A target has dependencies and tasks. The dependencies say "which other targets must be built before this target can be built?" You'll notice that the default target to build is c02.run, and the c02.run target says that it in turn depends on c02.build. Thus, the c02.build target must be executed before c02.run can be executed. Partitioning the buildfile this way not only makes it easier to understand, but it also allows you to choose what you want to do via the Ant command line; if you say 'ant c02.build,' then it will only compile the code, but if you say 'ant co2.run' (or, because of the default target, just 'ant'), then it will first make sure things have been built, and then run the examples.

So, for the project to be successful, targets c02.build and c02.run must first succeed, in that order. The c02.build target contains a single task, which is a command that actually does the work of bringing things up-to-date. This task runs the javac compiler on all the Java files in this current base directory; notice the ${} syntax used to produce the value of a previously-defined variable, and that the orientation of slashes in directory paths is not important, since Ant compensates depending on the operating system you run it on. The classpath attribute gives a directory list to add to Ant's classpath, and source specifies the compiler to use (this is actually only noticed by JDK 1.4 and beyond). Note that the Java compiler is responsible for sorting out the dependencies between the classes themselves, so you don't have to explicitly state inter-file dependencies like you must with make and C/C++ (this saves a lot of effort).

To run the programs in the directory (which, in this case, is only the single program HelloDate), this buildfile uses a task named antcall. This task does a recursive invocation of Ant on another target, which in this case just uses java to execute the program. Note that the java task has a taskname attribute; this attribute is actually available for all tasks, and is used when Ant outputs logging information.

As you might expect, the java tag also has options to establish the class name to be executed, and the classpath. In addition, the

fork="true"
failonerror="true"

attributes tell Ant to fork off a new process to run this program, and to fail the Ant build if the program fails. You can look up all the different tasks and their attributes in the documentation that comes with the Ant download.

The last target is one that's typically found in every buildfile; it allows you to say ant clean and delete all the files that have been created in order to perform this build. Whenever you create a buildfile, you should be careful to include a clean target, because you're the person who typically knows the most about what can be deleted and what should be preserved.

The clean target introduces some new syntax. You can delete single items with the one-line version of this task, like this:

<delete file="${basedir}/HelloDate.class"/>

The multiline version of the task allows you to specify a fileset, which is a more complex description of a set of files and may specify files to include and exclude by using wildcards. In this example, the filesets to delete include all files in this directory and all subdirectories that have a .class extension, and all files in the current subdirectory that end with Output.txt.

The buildfile shown here is fairly simple; within this book's source code tree (which is downloadable from www.BruceEckel.com) you'll find more complex buildfiles. Also, Ant is capable of doing much more that what we use for this book. For the full details of its capabilities, see the documentation that comes with the Ant installation.

15-3-3-1. Ant extensions▲

//: com:bruceeckel:tools:CheckVersion.java
// {RunByHand}
package com.bruceeckel.tools;
 
public class CheckVersion {
	public static void main(String[] args) {
		String version = System.getProperty("java.version");
		char minor = version.charAt(2);
		char point = version.charAt(4);
		if(minor < '4' || point < '1')
			throw new RuntimeException("JDK 1.4.1 or higher " +
				"is required to run the examples in this book.");
		System.out.println("JDK version "+ version + " found");
	}
} ///:~

<java
	taskname="CheckVersion"
	classname="com.bruceeckel.tools.CheckVersion"
	classpath="${basedir}"
	fork="true"
	failonerror="true"
/>

A revision control system is a class of tool that has been developed over many years to help manage large team programming projects. It has also turned out to be fundamental to the success of virtually all open-source projects, because open-source teams are almost always distributed globally via the Internet. So even if there are only two people working on a project, they benefit from using a revision control system.

The defacto standard revision control system for open-source projects is called Concurrent Versions System (CVS), available at www.cvshome.org. Because it is open-source and so many people know how to use it, CVS is also a common choice for closed projects. Some projects even use CVS as a way to distribute the system. CVS has the usual benefits of a popular open-source project: the code has been thoroughly reviewed, it's available for your review and modification, and flaws are rapidly corrected.

CVS keeps your code in a repository on a server. This server may be on a local area network, but it is typically available on the Internet so that people on the team can get updates without being at a particular location. To connect to CVS, you must have an assigned user name and password, so there's a reasonable level of security; for more security, you can use the ssh protocol (although these are Linux tools, they are readily available in Windows using Cygwin-see www.cygwin.com). Some graphical development environments (like the free Eclipse editor; see www.eclipse.org) provide excellent integration with CVS.

Once the repository is initialized by your system administrator, team members may get a copy of the code tree by checking it out. For example, once your machine is logged into the appropriate CVS server (details of which are omitted here), you can perform the initial checkout with a command like this:

cvs -z5 co TIJ3

This will connect with the CVS server and negotiate the checkout ('co') of the code repository called TIJ3. The '-z5' argument tells the CVS programs at both ends to communicate using a gzip compression level of 5 in order to speed up the transfer over the network.

Once this command is completed, you'll have a copy of the code repository on your local machine. In addition, you'll see that each directory in the repository has an additional subdirectory named CVS. This is where all the CVS information about the files in that directory are stored.

Now that you have your own copy of the CVS repository, you can make changes to the files in order to develop the project. Typically, these changes include corrections and feature additions along with test code and modified buildfiles necessary to compile and run the tests. You'll find that it's very unpopular to check in code that doesn't successfully run all its tests, because then everyone else on the team will get the broken code (and thus fail their builds).

When you've made your improvements and you're ready to check them in, you must go through a two-step process that is the crux of CVS code synchronization. First, you update your local repository to synchronize it with the main CVS repository by moving into the root of your local code repository and running this command:

cvs update -dP

At this point, you aren't required to log in because the CVS subdirectory keeps the login information for the remote repository, and the remote repository keeps signature information about your machine as a double check to verify your identity.

The '-dP' flag is optional; '-d' tells CVS to create any new directories on your local machine that might have been added to the main repository, and '-P' tells CVS to prune off any directories on your local machine that have been emptied on the main repository. Neither of these things happens by default.

The main activity of update, however, is quite interesting. You should actually run update on a regular basis, not just before you do a checkin, because it synchronizes your local repository with the main repository. If it finds any files in the main repository that are newer than files on your local repository, it brings the changes onto your local machine. However, it doesn't just copy the files, but instead does a line-by-line comparison of the files and patches the changes from the main repository into your local version. If you've made some changes to a file and someone else has made changes to the same file, CVS will patch the changes together as long as the changes don't happen to the same lines of code (CVS matches the contents of the lines, and not just the line numbers, so even if line numbers change, it will be able to synchronize properly). Thus, you can be working on the same file as someone else, and when you do an update, any changes the other person has committed to the main repository will be merged with your changes.

Of course, it's possible that two people might make changes to the same lines of the same file. This is an accident due to lack of communication; normally you'll tell each other what you're working on so as not to tread on each other's code (also, if files are so big that it makes sense for two different people to work on different parts of the same file, you might consider breaking up the big files into smaller files for easier project management). If this happens, CVS simply notes the collision and forces you to resolve it by fixing the lines of code that collide.

Note that no files from your machine are moved into the main repository during an update. The update brings only changed files from the main repository onto your machine and patches in any modifications you've made. So how do your modifications get into the main repository? This is the second step: the commit.

When you type

cvs commit

CVS will start up your default editor and ask you to write a description of your modification. This description will be entered into the repository so that others will know what's been changed. After that, your modified files will be placed into the main repository so they are available to everyone else the next time they do an update.

CVS has other capabilities, but checking out, updating, and committing are what you'll be doing most of the time. For detailed information about CVS, books are available, and the main CVS Web site has full documentation: www.cvshome.org. In addition, you can search on the Internet using Google or other search engines; there are some very nice condensed introductions to CVS that can get you started without bogging you down with too many details (the "Gentoo Linux CVS Tutorial" by Daniel Robbins (www.gentoo.org/doc/cvs-tutorial.html) is particularly straightforward).

By incorporating compilation and testing into your buildfiles, you can follow the practice of performing daily builds, advocated by the Extreme Programming folks and others. Regardless of the number of features that you currently have implemented, you always keep your system in a state in which it can be successfully built, so that if someone performs a checkout and runs Ant, the buildfile will perform all the compilations and run all the tests without failing.

This is a powerful technique. It means that you always have, as a baseline, a system that compiles and passes all its tests. At any time, you can always see what the true state of the development process is by examining the features that are actually implemented in the running system. One of the timesavers of this approach is that no one has to waste time coming up with a report explaining what is going on with the system; everybody can see for themselves by checking out a current build and running the program.

Running builds daily, or more often, also ensures that if someone (accidentally, we presume) checks in changes that cause tests to fail, you'll know about it in short order, before those bugs have a chance to propagate further problems in the system. Ant even has a task that will send email, because many teams set up their buildfile as a cron(97) job to automatically run daily, or even several times a day, and send email if it fails. There is also an open-source tool that automatically performs builds and provides a Web page to show the project status; see http://cruisecontrol.sourceforge.net.

The logging API provides multiple levels of reporting and the ability to change to a different level during program execution. Thus, you can dynamically set the logging level to any of the following states:

You can even inherit from java.util.Logging.Level (which has protected constructors) and define your own level. This could, for example, have a value of less than 300, so the level is less than FINEST. Then logging messages at your new level would not appear when the level is FINEST.

You can see the effect of trying out the different levels of logging in the following example:

//: c15:LoggingLevels.java
import com.bruceeckel.simpletest.*;
import java.util.logging.Level;
import java.util.logging.Logger;
import java.util.logging.Handler;
import java.util.logging.LogManager;
 
public class LoggingLevels {
	private static Test monitor = new Test();
	private static Logger
		lgr = Logger.getLogger("com"),
		lgr2 = Logger.getLogger("com.bruceeckel"),
		util = Logger.getLogger("com.bruceeckel.util"),
		test = Logger.getLogger("com.bruceeckel.test"),
		rand = Logger.getLogger("random");
	private static void logMessages() {
		lgr.info("com : info");
		lgr2.info("com.bruceeckel : info");
		util.info("util : info");
		test.severe("test : severe");
		rand.info("random : info");
	}
	public static void main(String[] args) {
		lgr.setLevel(Level.SEVERE);
		System.out.println("com level: SEVERE");
		logMessages();
		util.setLevel(Level.FINEST);
		test.setLevel(Level.FINEST);
		rand.setLevel(Level.FINEST);
		System.out.println("individual loggers set to FINEST");
		logMessages();
		lgr.setLevel(Level.SEVERE);
		System.out.println("com level: SEVERE");
		logMessages();
		monitor.expect("LoggingLevels.out");
	}
} ///:~

The first few lines of main( ) are necessary because the default level of logging messages that will be reported is INFO and greater (more severe). If you do not change this, then the messages of level CONFIG and below will not be reported (try taking out the lines to see this happen).

You can have multiple logger objects in your program, and these loggers are organized into a hierarchical tree, which can be programmatically associated with the package namespace. Child loggers keep track of their immediate parent and by default pass the logging records up to the parent.

The "root" logger object is always created by default, and is the base of the tree of logger objects. You get a reference to the root logger by calling the static method Logger.getLogger(""). Notice that it takes an empty string rather than no arguments.

Each Logger object can have one or more Handler objects associated with it. Each Handler object provides a strategy(98) for publishing the logging information, which is contained in LogRecord objects. To create a new type of Handler, you simply inherit from the Handler class and override the publish( ) method (along with flush( ) and close( ), to deal with any streams you may use in the Handler).

The root logger always has one associated handler by default, which sends output to the console. In order to access the handlers, you call getHandlers( ) on the Logger object. In the preceding example, we know that there's only one handler so we don't technically need to iterate through the list, but it's safer to do so in general because someone else may have added other handlers to the root logger. The default level of each handler is INFO, so in order to see all the messages, we set the level to ALL (which is the same as FINEST).

The levels array allows easy testing of all the Level values. The logger is set to each value and all the different logging levels are attempted. In the output you can see that only messages at the currently selected logging level, and those messages that are more severe, are reported.

A LogRecord is an example of a Messenger object, (99) whose job is simply to carry information from one place to another. All the methods in the LogRecord are getters and setters. Here's an example that dumps all the information stored in a LogRecord using the getter methods:

//: c15:PrintableLogRecord.java
// Override LogRecord toString()
import com.bruceeckel.simpletest.*;
import java.util.ResourceBundle;
import java.util.logging.*;
 
public class PrintableLogRecord extends LogRecord {
	private static Test monitor = new Test();
	public PrintableLogRecord(Level level, String str) {
		super(level, str);
	}
	public String toString() {
		String result = "Level<" + getLevel() + ">\n"
			+ "LoggerName<" + getLoggerName() + ">\n"
			+ "Message<" + getMessage() + ">\n"
			+ "CurrentMillis<" + getMillis() + ">\n"
			+ "Params";
		Object[] objParams = getParameters();
		if(objParams == null)
			result += "<null>\n";
		else
			for(int i = 0; i < objParams.length; i++)
				result += "  Param # <" + i + " value " +
					objParams[i].toString() + ">\n";
		result += "ResourceBundle<" + getResourceBundle()
			+ ">\nResourceBundleName<" + getResourceBundleName()
			+ ">\nSequenceNumber<" + getSequenceNumber()
			+ ">\nSourceClassName<" + getSourceClassName()
			+ ">\nSourceMethodName<" + getSourceMethodName()
			+ ">\nThread Id<" + getThreadID()
			+ ">\nThrown<" + getThrown() + ">";
		return result;
	}
	public static void main(String[] args) {
		PrintableLogRecord logRecord = new PrintableLogRecord(
			Level.FINEST, "Simple Log Record");
		System.out.println(logRecord);
		monitor.expect(new String[] {
			"Level<FINEST>",
			"LoggerName<null>",
			"Message<Simple Log Record>",
			"%% CurrentMillis<.+>",
			"Params<null>",
			"ResourceBundle<null>",
			"ResourceBundleName<null>",
			"SequenceNumber<0>",
			"SourceClassName<null>",
			"SourceMethodName<null>",
			"Thread Id<10>",
			"Thrown<null>"
		});
	}
} ///:~

PrintableLogRecord is a simple extension of LogRecord that overrides toString( ) to call all the getter methods available in LogRecord.

As noted previously, you can easily create your own handler by inheriting from Handler and defining publish( ) to perform your desired operations. However, there are predefined handlers that will probably satisfy your needs without doing any extra work:

For example, you often want to store logging output to a file. The FileHandler makes this easy:

//: c15:LogToFile.java
// {Clean: LogToFile.xml,LogToFile.xml.lck}
import com.bruceeckel.simpletest.*;
import java.util.logging.*;
 
public class LogToFile {
	private static Test monitor = new Test();
	private static Logger logger =
		Logger.getLogger("LogToFile");
	public static void main(String[] args) throws Exception {
		logger.addHandler(new FileHandler("LogToFile.xml"));
		logger.info("A message logged to the file");
		monitor.expect(new String[] {
			"%% .* LogToFile main",
			"INFO: A message logged to the file"
		});
	}
} ///:~

When you run this program, you'll notice two things. First, even though we're sending output to a file, you'll still see console output. That's because each message is converted to a LogRecord, which is first used by the local logger object, which passes it to its own handlers. At this point the LogRecord is passed to the parent object, which has its own handlers. This process continues until the root logger is reached. The root logger comes with a default ConsoleHandler, so the message appears on the screen as well as appearing in the log file (you can turn off this behavior by calling setUseParentHandlers(false)).

The second thing you'll notice is that the contents of the log file is in XML format, which will look something like this:

<?xml version="1.0" standalone="no"?>
<!DOCTYPE log SYSTEM "logger.dtd">
<log>
<record>
	<date>2002-07-08T12:18:17</date>
	<millis>1026152297750</millis>
	<sequence>0</sequence>
	<logger>LogToFile</logger>
	<level>INFO</level>
	<class>LogToFile</class>
	<method>main</method>
	<thread>10</thread>
	<message>A message logged to the file</message>
</record>
</log>

The default output format for a FileHandler is XML. If you want to change the format, you must attach a different Formatter object to the handler. Here, a SimpleFormatter is used for the file in order to output as plain text format:

//: c15:LogToFile2.java
// {Clean: LogToFile2.txt,LogToFile2.txt.lck}
import com.bruceeckel.simpletest.*;
import java.util.logging.*;
 
public class LogToFile2 {
	private static Test monitor = new Test();
	private static Logger logger =
		Logger.getLogger("LogToFile2");
	public static void main(String[] args) throws Exception {
		FileHandler logFile= new FileHandler("LogToFile2.txt");
		logFile.setFormatter(new SimpleFormatter());
		logger.addHandler(logFile);
		logger.info("A message logged to the file");
		monitor.expect(new String[] {
			"%% .* LogToFile2 main",
			"INFO: A message logged to the file"
		});
	}
} ///:~

The LogToFile2.txt file will look like this:

Jul 8, 2002 12:35:17 PM LogToFile2 main
INFO: A message logged to the file

15-4-3-1. Multiple Handlers▲

//: c15:MultipleHandlers.java
// {Clean: MultipleHandlers.xml,MultipleHandlers.xml.lck}
import com.bruceeckel.simpletest.*;
import java.util.logging.*;
 
public class MultipleHandlers {
	private static Test monitor = new Test();
	private static Logger logger =
		Logger.getLogger("MultipleHandlers");
	public static void main(String[] args) throws Exception {
		FileHandler logFile =
			new FileHandler("MultipleHandlers.xml");
		logger.addHandler(logFile);
		logger.addHandler(new ConsoleHandler());
		logger.warning("Output to multiple handlers");
		monitor.expect(new String[] {
			"%% .* MultipleHandlers main",
			"WARNING: Output to multiple handlers",
			"%% .* MultipleHandlers main",
			"WARNING: Output to multiple handlers"
		});
	}
} ///:~

//: c15:MultipleHandlers2.java
// {Clean: MultipleHandlers2.xml,MultipleHandlers2.xml.lck}
import com.bruceeckel.simpletest.*;
import java.util.logging.*;
 
public class MultipleHandlers2 {
	private static Test monitor = new Test();
	private static Logger logger =
		Logger.getLogger("MultipleHandlers2");
	public static void main(String[] args) throws Exception {
		FileHandler logFile =
			new FileHandler("MultipleHandlers2.xml");
		logger.addHandler(logFile);
		logger.addHandler(new ConsoleHandler());
		logger.setUseParentHandlers(false);
		logger.warning("Output to multiple handlers");
		monitor.expect(new String[] {
			"%% .* MultipleHandlers2 main",
			"WARNING: Output to multiple handlers"
		});
	}
} ///:~

15-4-3-2. Writing your own Handlers▲

//: c15:CustomHandler.java
// How to write custom handler
import com.bruceeckel.simpletest.*;
import java.util.logging.*;
import java.util.*;
 
public class CustomHandler {
	private static Test monitor = new Test();
	private static Logger logger =
		Logger.getLogger("CustomHandler");
	private static List strHolder = new ArrayList();
	public static void main(String[] args) {
		logger.addHandler(new Handler() {
			public void publish(LogRecord logRecord) {
				strHolder.add(logRecord.getLevel() + ":");
				strHolder.add(logRecord.getSourceClassName()+":");
				strHolder.add(logRecord.getSourceMethodName()+":");
				strHolder.add("<" + logRecord.getMessage() + ">");
				strHolder.add("\n");
			}
			public void flush() {}
			public void close() {}
		});
		logger.warning("Logging Warning");
		logger.info("Logging Info");
		System.out.print(strHolder);
		monitor.expect(new String[] {
			"%% .* CustomHandler main",
			"WARNING: Logging Warning",
			"%% .* CustomHandler main",
			"INFO: Logging Info",
			"[WARNING:, CustomHandler:, main:, " +
			"<Logging Warning>, ",
			", INFO:, CustomHandler:, main:, <Logging Info>, ",
			"]"
		});
	}
} ///:~

When you write the code to send a logging message to a Logger object, you often decide, at the time you're writing the code, what level the logging message should be (the logging API certainly allows you to devise more complex systems wherein the level of the message can be determined dynamically, but this is less common in practice). The Logger object has a level that can be set so that it can decide what level of message to accept; all others will be ignored. This can be thought of as a basic filtering functionality, and it's often all you need.

Sometimes, however, you need more sophisticated filtering so that you can decide whether to accept or reject a message based on something more than just the current level. To accomplish this you can write custom Filter objects. Filter is an interface that has a single method, boolean isLoggable(LogRecord record), which decides whether or not this particular LogRecord is interesting enough to report.

Once you create a Filter, you register it with either a Logger or a Handler by using the setFilter( ) method. For example, suppose you'd like to only log reports about Ducks:

//: c15:SimpleFilter.java
import com.bruceeckel.simpletest.*;
import java.util.logging.*;
 
public class SimpleFilter {
	private static Test monitor = new Test();
	private static Logger logger =
		Logger.getLogger("SimpleFilter");
	static class Duck {};
	static class Wombat {};
	static void sendLogMessages() {
		logger.log(Level.WARNING,
			"A duck in the house!", new Duck());
		logger.log(Level.WARNING,
			"A Wombat at large!", new Wombat());
	}
	public static void main(String[] args) {
		sendLogMessages();
		logger.setFilter(new Filter() {
			public boolean isLoggable(LogRecord record) {
				Object[] params = record.getParameters();
				if(params == null)
					return true; // No parameters
				if(record.getParameters()[0] instanceof Duck)
					return true;  // Only log Ducks
				return false;
			}
		});
		logger.info("After setting filter..");
		sendLogMessages();
		monitor.expect(new String[] {
			"%% .* SimpleFilter sendLogMessages",
			"WARNING: A duck in the house!",
			"%% .* SimpleFilter sendLogMessages",
			"WARNING: A Wombat at large!",
			"%% .* SimpleFilter main",
			"INFO: After setting filter..",
			"%% .* SimpleFilter sendLogMessages",
			"WARNING: A duck in the house!"
		});
	}
} ///:~

Before setting the Filter, messages about Ducks and Wombats are reported. The Filter is created as an anonymous inner class that looks at the LogRecord parameter to see if a Duck was passed as an extra argument to the log( ) method. If so, it returns true to indicate that the message should be processed.

Notice that the signature of getParameters( ) says that it will return an Object[]. However, if no additional arguments have been passed to the log( ) method, getParameters( ) will return null (in violation of its signature-this is a bad programming practice). So instead of assuming that an array is returned (as promised) and checking to see if it is of zero length, we must check for null. If you don't do this correctly, then the call to logger.info( ) will cause an exception to be thrown.

A Formatter is a way to insert a formatting operation into a Handler's processing steps. If you register a Formatter object with a Handler, then before the LogRecord is published by the Handler, it is first sent to the Formatter. After formatting, the LogRecord is returned to the Handler, which then publishes it.

To write a custom Formatter,extend the Formatter class and override format(LogRecord record). Then, register the Formatter with the Handler by using the setFormatter( ) call, as seen here:

//: c15:SimpleFormatterExample.java
import com.bruceeckel.simpletest.*;
import java.util.logging.*;
import java.util.*;
 
public class SimpleFormatterExample {
	private static Test monitor = new Test();
	private static Logger logger =
		Logger.getLogger("SimpleFormatterExample");
	private static void logMessages() {
		logger.info("Line One");
		logger.info("Line Two");
	}
	public static void main(String[] args) {
		logger.setUseParentHandlers(false);
		Handler conHdlr = new ConsoleHandler();
		conHdlr.setFormatter(new Formatter() {
			public String format(LogRecord record) {
				return record.getLevel()  + "  :  "
					+ record.getSourceClassName()  + " -:- "
					+ record.getSourceMethodName()  + " -:- "
					+ record.getMessage() + "\n";
			}
		});
		logger.addHandler(conHdlr);
		logMessages();
		monitor.expect(new String[] {
			"INFO  :  SimpleFormatterExample -:- logMessages "
				+ "-:- Line One",
			"INFO  :  SimpleFormatterExample -:- logMessages "
				+ "-:- Line Two"
		});
	}
} ///:~

Remember that a logger like myLogger has a default handler that it gets from the parent logger (the root logger, in this case). Here, we are turning off the default handler by calling setUseParentHandlers(false), and then adding in a console handler to use instead. The new Formatter is created as an anonymous inner class in the setFormatter( ) statement. The overridden format( ) statement simply extracts some of the information from the LogRecord and formats it into a string.

You can actually have one of your logging handlers send you an email so that you can be automatically notified of important problems. The following example uses the JavaMail API to develop a mail user agent to send an email.

The JavaMail API is a set of classes that interface to the underlying mailing protocol (IMAP, POP, SMTP). You can devise a notification mechanism on some exceptional condition in the running code by registering an additional Handler to send an email.

//: c15:EmailLogger.java
// {RunByHand} Must be connected to the Internet
// {Depends: mail.jar,activation.jar}
import java.util.logging.*;
import java.io.*;
import java.util.Properties;
import javax.mail.*;
import javax.mail.internet.*;
 
public class EmailLogger {
	private static Logger logger =
		Logger.getLogger("EmailLogger");
	public static void main(String[] args) throws Exception {
		logger.setUseParentHandlers(false);
		Handler conHdlr = new ConsoleHandler();
		conHdlr.setFormatter(new Formatter() {
			public String format(LogRecord record) {
				return record.getLevel() + "  :  "
					+ record.getSourceClassName() + ":"
					+ record.getSourceMethodName() + ":"
					+ record.getMessage() + "\n";
			}
		});
		logger.addHandler(conHdlr);
		logger.addHandler(
			new FileHandler("EmailLoggerOutput.xml"));
		logger.addHandler(new MailingHandler());
		logger.log(Level.INFO,
			"Testing Multiple Handlers", "SendMailTrue");
	}
}
 
// A handler that sends mail messages
class MailingHandler extends Handler {
	public void publish(LogRecord record) {
		Object[] params = record.getParameters();
		if(params == null) return;
		// Send mail only if the parameter is true
		if(params[0].equals("SendMailTrue")) {
			new MailInfo("bruce@theunixman.com",
			new String[] { "bruce@theunixman.com" },
			"smtp.theunixman.com", "Test Subject",
			"Test Content").sendMail();
		}
	}
	public void close() {}
	public void flush() {}
}
 
class MailInfo {
	private String fromAddr;
	private String[] toAddr;
	private String serverAddr;
	private String subject;
	private String message;
	public MailInfo(String from, String[] to,
		String server, String subject, String message) {
		fromAddr = from;
		toAddr = to;
		serverAddr = server;
		this.subject = subject;
		this.message = message;
	}
	public void sendMail() {
		try {
			Properties prop = new Properties();
			prop.put("mail.smtp.host", serverAddr);
			Session session =
				Session.getDefaultInstance(prop, null);
			session.setDebug(true);
			// Create a message
			Message mimeMsg = new MimeMessage(session);
			// Set the from and to address
			Address addressFrom = new InternetAddress(fromAddr);
			mimeMsg.setFrom(addressFrom);
			Address[] to = new InternetAddress[toAddr.length];
			for(int i = 0; i < toAddr.length; i++)
				to[i] = new InternetAddress(toAddr[i]);
			mimeMsg.setRecipients(Message.RecipientType.TO,to);
			mimeMsg.setSubject(subject);
			mimeMsg.setText(message);
			Transport.send(mimeMsg);
		} catch (Exception e) {
			throw new RuntimeException(e);
		}
	}
} ///:~

MailingHandler is one of the Handlers registered with the logger. To send an email, the MailingHandler uses the MailInfo object. When a logging message is sent with an additional parameter of "SendMailTrue," the MailingHandler sends an email.

The MailInfo object contains the necessary state information, such as the to address, from address, and the subject information required to send an email. This state information is provided to the MailInfo object through the constructor when it is instantiated.

To send an email you must first establish a Session with the Simple Mail Transfer Protocol (SMTP) server. This is done by passing the address of the server inside a Properties object, in a property named mail.smtp.host. You establish a session by calling Session.getDefaultInstance( ), passing it the Properties object as the first argument. The second argument is an instance of Authenticator that may be used for authenticating the user. Passing a null value for the Authenticator argument specifies no authentication. If the debugging flag in the Properties object is set, information regarding the communication between the SMTP server and the program will be printed.

MimeMessage is an abstraction of an Internet email message that extends the class Message. It constructs a message that complies with the MIME (Multipurpose Internet Mail Extensions) format. A MimeMessage is constructed by passing it an instance of Session. You may set the from and to addresses by creating an instance of InternetAddress class (a subclass of Address). You send the message using the static call Transport.send( ) from the abstract class Transport. An implementation of Transport uses a specific protocol (generally SMTP) to communicate with the server to send the message.

Although not mandatory, it's advisable to give a logger the name of the class in which it is used. This allows you to manipulate the logging level of groups of loggers that reside in the same package hierarchy, at the granularity of the directory package structure. For example, you can modify all the logging levels of all the packages in com, or just the ones in com.bruceeckel, or just the ones in com.bruceeckel.util, as shown in the following example:

//: c15:LoggingLevelManipulation.java
import com.bruceeckel.simpletest.*;
import java.util.logging.Level;
import java.util.logging.Logger;
import java.util.logging.Handler;
import java.util.logging.LogManager;
 
public class LoggingLevelManipulation {
	private static Test monitor = new Test();
	private static Logger
		lgr = Logger.getLogger("com"),
		lgr2 = Logger.getLogger("com.bruceeckel"),
		util = Logger.getLogger("com.bruceeckel.util"),
		test = Logger.getLogger("com.bruceeckel.test"),
		rand = Logger.getLogger("random");
	static void printLogMessages(Logger logger) {
		logger.finest(logger.getName() + " Finest");
		logger.finer(logger.getName() + " Finer");
		logger.fine(logger.getName() + " Fine");
		logger.config(logger.getName() + " Config");
		logger.info(logger.getName() + " Info");
		logger.warning(logger.getName() + " Warning");
		logger.severe(logger.getName() + " Severe");
	}
	static void logMessages() {
		printLogMessages(lgr);
		printLogMessages(lgr2);
		printLogMessages(util);
		printLogMessages(test);
		printLogMessages(rand);
	}
	static void printLevels() {
		System.out.println(" -- printing levels -- "
			+ lgr.getName() + " : " + lgr.getLevel()
			+ " " + lgr2.getName() + " : " + lgr2.getLevel()
			+ " " + util.getName() + " : " + util.getLevel()
			+ " " + test.getName() + " : " + test.getLevel()
			+ " " + rand.getName() + " : " + rand.getLevel());
	}
	public static void main(String[] args) {
		printLevels();
		lgr.setLevel(Level.SEVERE);
		printLevels();
		System.out.println("com level: SEVERE");
		logMessages();
		util.setLevel(Level.FINEST);
		test.setLevel(Level.FINEST);
		rand.setLevel(Level.FINEST);
		printLevels();
		System.out.println(
			"individual loggers set to FINEST");
		logMessages();
		lgr.setLevel(Level.FINEST);
		printLevels();
		System.out.println("com level: FINEST");
		logMessages();
		monitor.expect("LoggingLevelManipulation.out");
	}
} ///:~

As you can see in this code, if you pass getLogger( ) a string representing a namespace, the resulting Logger will control the severity levels of that namespace; that is, all the packages within that namespace will be affected by changes to the severity level of the logger.

Each Logger keeps a track of its existing ancestor Logger. If a child logger already has a logging level set, then that level is used instead of the parent's logging level. Changing the logging level of the parent does not affect the logging level of the child once the child has its own logging level.

Although the level of individual loggers is set to FINEST, only messages with a logging level equal to or more severe than INFO are printed because we are using the ConsoleHandler of the root logger, which is at INFO.

Because it isn't in the same namespace, the logging level of random remains unaffected when the logging level of the logger com or com.bruceeckel is changed.

At first glance, the Java logging API can seem rather over-engineered for most programming problems. The extra features and abilities don't come in handy until you start building larger projects. In this section we'll look at these features and recommended ways to use them. If you're only using logging on smaller projects, you probably won't need to use these features.

15-4-8-1. Configuration files▲

//:! c15:log.prop
#### Configuration File ####
# Global Params
# Handlers installed for the root logger
handlers= java.util.logging.ConsoleHandler java.util.logging.FileHandler
# Level for root logger-is used by any logger 
# that does not have its level set
.level= FINEST
# Initialization class-the public default constructor 
# of this class is called by the Logging framework
config = ConfigureLogging
 
# Configure FileHandler
# Logging file name - %u specifies unique
java.util.logging.FileHandler.pattern = java%g.log
# Write 100000 bytes before rotating this file
java.util.logging.FileHandler.limit = 100000
# Number of rotating files to be used
java.util.logging.FileHandler.count = 3
# Formatter to be used with this FileHandler
java.util.logging.FileHandler.formatter =   java.util.logging.SimpleFormatter
 
# Configure ConsoleHandler
java.util.logging.ConsoleHandler.level = FINEST
java.util.logging.ConsoleHandler.formatter = java.util.logging.SimpleFormatter
 
# Set Logger Levels #
com.level=SEVERE
com.bruceeckel.level = FINEST
com.bruceeckel.util.level = INFO
com.bruceeckel.test.level = FINER
random.level= SEVERE
///:~

15-4-8-2. Rotating log files▲

java -Djava.util.logging.config.file=log.prop ConfigureLogging

//: c15:ConfigureLogging.java
// {JVMArgs: -Djava.util.logging.config.file=log.prop}
// {Clean: java0.log,java0.log.lck}
import com.bruceeckel.simpletest.*;
import java.util.logging.*;
 
public class ConfigureLogging {
	private static Test monitor = new Test();
	static Logger lgr = Logger.getLogger("com"),
		lgr2 = Logger.getLogger("com.bruceeckel"),
		util = Logger.getLogger("com.bruceeckel.util"),
		test = Logger.getLogger("com.bruceeckel.test"),
		rand = Logger.getLogger("random");
	public ConfigureLogging() {
		/* Set Additional formatters, Filters and Handlers for
		   the loggers here. You cannot specify the Handlers
		   for loggers except the root logger from the
		   configuration file. */
	}
	public static void main(String[] args) {
		sendLogMessages(lgr);
		sendLogMessages(lgr2);
		sendLogMessages(util);
		sendLogMessages(test);
		sendLogMessages(rand);
		monitor.expect("ConfigureLogging.out");
	}
	private static void sendLogMessages(Logger logger) {
		System.out.println(" Logger Name : "
			+ logger.getName() + " Level: " + logger.getLevel());
		logger.finest("Finest");
		logger.finer("Finer");
		logger.fine("Fine");
		logger.config("Config");
		logger.info("Info");
		logger.warning("Warning");
		logger.severe("Severe");
	}
} ///:~

15-4-8-3. Suggested practices▲

config = ConfigureLogging1 ConfigureLogging2 Bar Baz

Although this has been a fairly thorough introduction to the logging API, it doesn't include everything. For instance, we haven't talked about the LogManager or details of the various built-in handlers, such as MemoryHandler, FileHandler, ConsoleHandler, etc. You should go to the JDK documentation for further details.

The Java Debugger (JDB) is a command-line debugger that ships with the JDK. JDB is at least conceptually a descendant of the Gnu Debugger (GDB, which was inspired by the original Unix DB), in terms of the instructions for debugging and its command-line interface. JDB is useful for learning about debugging and performing simpler debugging tasks, and it's helpful to know that it's always available wherever the JDK is installed. However, for larger projects you'll probably want to use a graphical debugger, described later.

Suppose you've written the following program:

//: c15:SimpleDebugging.java
// {ThrowsException}
public class SimpleDebugging {
	private static void foo1() {
		System.out.println("In foo1");
		foo2();
	}
	private static void foo2() {
		System.out.println("In foo2");
		foo3();
	}
	private static void foo3() {
		System.out.println("In foo3");
		int j = 1;
		j--;
		int i = 5 / j;
	}
	public static void main(String[] args) {
		foo1();
	}
} ///:~

If you look at foo3( ), the problem is obvious; you're dividing by zero. But suppose this code is buried in a large program (as is implied here by the sequence of calls) and you don't know where to start looking for the problem. As it turns out, the exception that will be thrown will give enough information for you to locate the problem (this is just one of the great things about exceptions). But let's just suppose that the problem is more difficult than that, and that you need to drill into it more deeply and get more information than what an exception provides.

To run JDB, you must tell the compiler to generate debugging information by compiling SimpleDebugging.java with the -g flag. Then you start debugging the program with the command line:

jdb SimpleDebugging

This brings up JDB and gives you a command prompt. You can view the list of available JDB commands by typing '?' at the prompt.

Here's an interactive debugging trace that shows how to chase down a problem:

Initializing jdb ...
> catch Exception

The > indicates that JDB is waiting for a command, and the commands typed in by the user are shown in bold. The command catch Exception causes a breakpoint to be set at any point where an exception is thrown (however, the debugger will stop anyway, even if you don't explicitly give this comment-exceptions appear to be default breakpoints in JDB).

Deferring exception catch Exception.
It will be set after the class is loaded.
> run

Now the program will rununtil the next breakpoint, which in this case is where the exception occurs. Here's the result of the run command:

run SimpleDebugging
>
VM Started: In foo1
In foo2
In foo3
Exception occurred: java.lang.ArithmeticException (uncaught)"thread=main", SimpleDebugging.foo3(), line=18 bci=15
18        int i = 5 / j;

The program runs until line 18, where the exception generated, but JDB does not exit when it hits the exception. The debugger also displays the line of code that caused the exception. You can list the point where the execution stopped in the program source by the list command as shown here:

main[1] list
14      private static void foo3() {
15        System.out.println("In foo3");
16        int j = 1;
17        j--;
18 =>     int i = 5 / j;
19      }
20
21      public static void main(String[] args) {
22        foo1();
23      }

The pointer ("=>") in this listing shows the current point from where the execution will resume. You could resume the execution by the cont (continue) command. But doing that will make JDB exit at the exception, printing the stack trace.

The locals command dumps the value of all the local variables:

main[1] locals
Method arguments:
Local variables:
j = 0

You can see that the value of j=0 is what caused the exception.

The wherei command prints the stack frames pushed in the method stack of the current thread:

main[1] wherei
[1] SimpleDebugging.foo3 (SimpleDebugging.java:18), pc = 15
[2] SimpleDebugging.foo2 (SimpleDebugging.java:11), pc = 8
[3] SimpleDebugging.foo1 (SimpleDebugging.java:6), pc = 8
[4] SimpleDebugging.main (SimpleDebugging.java:22), pc = 0

Each line after the wherei command represents a method call and the point where the call will return (which is shown by the value of the program counter pc). Here the calling sequence was main( ), foo1( ), foo2( ),and foo3( ). You can pop the stack frame pushed when the call was made to foo3( ) with the pop command:

main[1] pop
main[1] wherei
[1] SimpleDebugging.foo2 (SimpleDebugging.java:11), pc = 8
[2] SimpleDebugging.foo1 (SimpleDebugging.java:6), pc = 8
[3] SimpleDebugging.main (SimpleDebugging.java:22), pc = 0

You can make the JDB step through the call to foo3( ) againwith the reenter command:

main[1] reenter
>
Step completed: "thread=main", SimpleDebugging.foo3(), line=15 bci=0
System.out.println("In foo3");

The list command shows us that the execution begins at the start of foo3( ):

main[1] list
11        foo3();
12      }
13
14      private static void foo3() {
15 =>     System.out.println("In foo3");
16        int j = 1;
17        j--;
18        int i = 5 / j;
19      }
20

JDB also allows you to modify the value of the local variables. The divide by zero that was caused by executing this piece of code the last time can be avoided by changing the value of j. You can do this directly in the debugger, so you can continue debugging the program without going back and changing the source file. Before you set the value of j, you will have to execute through line 25 since that is where j is declared.

main[1] step
> In foo3
 
Step completed: "thread=main", SimpleDebugging.foo3(), line=16 bci=8
16        int j = 1;
 
main[1] step
>
Step completed: "thread=main", SimpleDebugging.foo3(), line=17 bci=10
17        j--;
 
main[1] list
13
14      private static void foo3() {
15        System.out.println("In foo3");
16        int j = 1;
17 =>     j--;
18        int i = 5 / j;
19      }
20
21      public static void main(String[] args) {
22        foo1();

At this point, j is defined and you can set its value so that the exception can be avoided.

main[1] set j=6
 j=6 = 6
main[1] next
>
Step completed: "thread=main", SimpleDebugging.foo3(), line=18 bci=13
18        int i = 5 / j;
main[1] next
>
Step completed: "thread=main", SimpleDebugging.foo3(), line=19 bci=17
19      }
main[1] next
>
Step completed: "thread=main", SimpleDebugging.foo2(), line=12 bci=11
12      }
main[1] list
8
9      private static void foo2() {
10        System.out.println("In foo2");
11        foo3();
12 =>   }
13
14      private static void foo3() {
15        System.out.println("In foo3");
16        int j = 1;
17        j--; 
main[1] next
>
Step completed: "thread=main", SimpleDebugging.foo1(), line=7 bci=11
7      }
main[1] list
3    public class SimpleDebugging {
4      private static void foo1() {
5        System.out.println("In foo1");
6        foo2();
7 =>   }
8
9      private static void foo2() {
10        System.out.println("In foo2");
11        foo3();
12      } 
main[1] next
>
Step completed: "thread=main", SimpleDebugging.main(), line=23 bci=3
23      }
 
main[1] list
19      }
20
21      public static void main(String[] args) {
22        foo1();
23 =>   }
24    } ///:~ 
main[1] next
>
The application exited

next executes a line at a time. You can see that the exception is avoided and we can continue stepping through the program. list is used to show the position in the program from where execution will proceed.

Using a command-line debugger like JDB can be inconvenient. You must use explicit commands to do things like looking at the state of the variables (locals, dump), listing the point of execution in the source code (list), finding out the threads in the system(threads), setting breakpoints (stop in, stop at), etc. A graphical debugger allows you to do all these things with a few clicks and also view the latest details of program being debugged without using explicit commands.

Thus, although you may want to get started by experimenting with JDB, you'll probably find it much more productive to learn to use a graphical debugger in order to quickly track down your bugs. During the development of this edition of this book, we began using IBM's Eclipse editor and development environment, which contains a very good graphical debugger for Java. Eclipse is well designed and implemented, and you can download it for free from www.Eclipse.org (this is a free tool, not a demo or shareware-thanks to IBM for investing the money, time, and effort to make this available to everyone).

Other free development tools have graphical debuggers as well, such as Sun's Netbeans and the free version of Borland's JBuilder.

Here is the kind of data a profiler can show for memory usage:

• Number of object allocations for a specific type.
• Places where the object allocations are taking place.
• Methods involved in allocation of instances of this class.
• Loitering objects: objects that are allocated, not used, and not garbage collected. These keep increasing the size of the JVM heap and represent memory leaks, which can cause an out-of-memory error or excessive overhead on the garbage collector.
• Excessive allocation of temporary objects that increase the work of the garbage collector and thus reduce the performance of the application.
• Failure to release instances added to a collection and not removed (this is a special case of loitering objects).

Profilers also keep track of how much time the CPU spends in various parts of your code. They can tell you:

• The number of times a method was invoked.
• The percentage of CPU time utilized by each method. If this method calls other methods, the profiler can tell you the amount of time spent in these other methods.
• Total absolute time spent by each method, including the time it waits for I/O, locks, etc. This time depends on the available resources of the system.

This way you can decide which sections of your code need optimizing.

Coverage testing shows the lines of code that were not executed during the test. This can draw your attention to code that is not used and might therefore be a candidate for removal or refactoring.

To get coverage testing information for SimpleDebugging.java, you use the command:

java -Xrunjcov:type=M SimpleDebugging

As an experiment, try putting lines of code that will not be executed into SimpleDebugging.java (you'll have to be somewhat clever about this since the compiler can detect unreachable lines of code).

The profiler agent communicates the events it is interested in to the JVM. The JVM profiling interface supports the following events:

• Enter and exit a method
• Allocate, move, and free an object
• Create and delete a heap arena
• Begin and end a garbage collection cycle
• Allocate and free a JNI global reference
• Allocate and free a JNI weak global reference
• Load and unload a compiled method
• Start and end a thread
• Class file data ready for instrumentation
• Load and unload a class
• For a Java monitor under contention: Wait To Enter , entered, and exit
• For a raw monitor under contention: Wait To Enter, entered, and exit
• For an uncontended Java monitor: Wait and waited
• Monitor Dump
• Heap Dump
• Object Dump
• Request to dump or reset profiling data
• JVM initialization and shutdown

While profiling, the JVM sends these events to the profiler agent, which then transfers the desired information to the profiler front end, which can be a process running on another machine, if desired.

The example in this section shows how you can run the profiler that ships with the JDK. Although the information from this profiler is in the somewhat crude form of text files rather than the graphical representation that most commercial profilers produce, it still provides valuable help in determining the characteristics of your program.

You run the profiler by passing an extra argument to the JVM when you invoke the program. This argument must be a single string, without any spaces after the commas, like this (although it should be on a single line, it has wrapped in the book):

java -Xrunhprof:heap=sites,cpu=samples,depth=10,monitor=y,thread=y,doe=y ListPerformance

• The heap=sites tells the profiler to write information about memory utilization on the heap, indicating where it was allocated.
• cpu=samples tells the profiler to do statistical sampling to determine CPU use.
• depth=10 indicates the depth of the trace for threads.
• thread=y tells the profiler to identify the threads in the stack traces.
• doe=y tells the profiler to produce dump of profiling data on exit.

The following listing contains only a portion of the file produced by HPROF. The output file is created in the current directory and is named java.hprof.txt.

The beginning of java.hprof.txt describes the details of the remaining sections in the file. The data produced by the profiler is in different sections; for example, TRACE represents a trace section in the file. You will see many TRACE sections, each numbered so that they can be referenced later.

The SITES section shows memory allocation sites. The section has several rows, sorted by the number of bytes that are allocated and are being referenced-the live bytes. The memory is listed in bytes. The column self represents the percentage of memory taken up by this site, the next column, accum, represents the cumulative memory percentage. The live bytes and live objects columns represent the number of live bytes at this site and the number of objects that were created that consumes these bytes. The allocated bytes and objects represent the total number of objects and bytes that are instantiated, including the ones being used and the ones not being used. The difference in the number of bytes listed in allocated and live represent the bytes that can be garbage collected. The trace column actually references a TRACE in the file. The first row references trace 668 as shown below. The name represents the class whose instance was created.

SITES BEGIN (ordered by live bytes) Thu Jul 18 11:23:06 2002
          percent         live       alloc'ed  stack class
 rank   self  accum    bytes objs   bytes objs trace name
    1 59.10% 59.10%   573488    3  573488    3   668 java.lang.Object
    2  7.41% 66.50%    71880  543   72624  559     1 [C
    3  7.39% 73.89%    71728    3   82000   10   649 java.lang.Object
    4  5.14% 79.03%    49896  232   49896  232     1 [B
    5  2.53% 81.57%    24592  310   24592  310     1 [S 
 
TRACE 668: (thread=1)
	java.util.Vector.ensureCapacityHelper(Vector.java:222)
	java.util.Vector.insertElementAt(Vector.java:564)
	java.util.Vector.add(Vector.java:779)
	java.util.AbstractList$ListItr.add(AbstractList.java:495)
	ListPerformance$3.test(ListPerformance.java:40)
	ListPerformance.test(ListPerformance.java:63)
	ListPerformance.main(ListPerformance.java:93)

This trace shows the method call sequence that allocates the memory. If you go through the trace as indicated by the line numbers, you will find that an object allocation takes place on line number 222 of Vector.java:

elementData = new Object[newCapacity];

This helps you discover parts of the program that use up significant amounts of memory (59.10 %, in this case).

Note the [C in SITE 1 represents the primitive type char. This is the internal representation of the JVM for the primitive types.

The CPU SAMPLES section shows the CPU utilization. Here is part of a trace from this section.

SITES END
CPU SAMPLES BEGIN (total = 514) Thu Jul 18 11:23:06 2002
rank   self  accum   count trace method
   1 28.21% 28.21%     145   662 java.util.AbstractList.iterator
   2 12.06% 40.27%      62   589 java.util.AbstractList.iterator
   3 10.12% 50.39%      52   632 java.util.LinkedList.listIterator
   4  7.00% 57.39%      36   231 java.io.FileInputStream.open
   5  5.64% 63.04%      29   605 ListPerformance$4.test
   6  3.70% 66.73%      19   636 java.util.LinkedList.addBefore

The organization of this listing is similar to the organization of the SITES listings. The rows are sorted by CPU utilization. The row on the top has the maximum CPU utilization, as indicated in the self column. The accum column lists the cumulative CPU utilization. The count field specifies the number of times this trace was active. The next two columns specify the trace number and the method that took this time.

Consider the first row of the CPU SAMPLES section. 28.12% of total CPU time was utilized in the method java.util.AbstractList.iterator( ),and it was called 145 times. The details of this call can be seen by looking at trace number 662:

TRACE 662: (thread=1)
	java.util.AbstractList.iterator(AbstractList.java:332)
	ListPerformance$2.test(ListPerformance.java:28)
	ListPerformance.test(ListPerformance.java:63)
	ListPerformance.main(ListPerformance.java:93)

You can infer that iterating through a list takes a significant amount of time.

For large projects it is often more helpful to have the information represented in graphical form. A number of profilers produce graphical displays, but coverage of these is beyond the scope of this book.

• Avoid sacrificing code readability for performance.
• Performance should not be considered in isolation. Weigh the amount of effort required versus the advantage gained.
• Performance can be a concern in big projects but is often not an issue for small projects.
• Getting a program to work should have a higher priority than delving into the performance of the program. Once you have a working program you can use the profiler to make it more efficient. Performance should be considered during the initial design/development process only if it is determined to be a critical factor.
• Do not make assumptions about where the bottlenecks are. Run a profiler to get the data.
• Whenever possible try to explicitly discard an instance by setting it to null. This can sometimes be a useful hint to the garbage collector.
• The size of the program matters. Performance optimization is generally valuable only when the size of the project is large, it runs for a long time and speed is an issue.
• static final variables can be optimized by the JVM to improve program speed. Program constants should thus be declared as static and final.