Invariant Properties

  • rss
  • Home

Adding Database Logging to JUnit3

Bear Giles | August 16, 2015

We have written many thousands of JUnit3 tests over the last decade and are now trying to consolidate the results in a database instead of scattered log files. It turns out to be remarkably easy to extend the TestCase class to do this. Note: this approach does not directly apply to JUnit4 or other test frameworks but it’s usually possible to do something analogous.

The tested class and its test

For demonstration purposes we can define a class with a single method to test.

  1. public class MyTestedClass {
  2.  
  3.     public String op(String a, String b) {
  4.         return ((a == null) ? "" : a) + ":" + ((b == null) ? "" : b);
  5.     }
  6. }
public class MyTestedClass {

    public String op(String a, String b) {
        return ((a == null) ? "" : a) + ":" + ((b == null) ? "" : b);
    }
}

A class with a single method to be tested is less of a restriction than you might think. We are only testing four methods in the thousands of tests I mentioned earlier.

Here are a handful of tests for the class above.

  1. public class MySimpleTest extends SimpleTestCase {
  2.  
  3.     private MyTestedClass obj = new MyTestedClass();
  4.  
  5.     public void test1() {
  6.         assertEquals("a:b", obj.op("a", "b"));
  7.     }
  8.  
  9.     public void test2() {
  10.         assertEquals(":b", obj.op(null, "b"));
  11.     }
  12.  
  13.     public void test3() {
  14.         assertEquals("a:", obj.op("a", null));
  15.     }
  16.  
  17.     public void test4() {
  18.         assertEquals(":", obj.op(null, null));
  19.     }
  20.  
  21.     public void test5() {
  22.         // this will fail
  23.         assertEquals(" : ", obj.op(null, null));
  24.     }
  25. }
public class MySimpleTest extends SimpleTestCase {

    private MyTestedClass obj = new MyTestedClass();

    public void test1() {
        assertEquals("a:b", obj.op("a", "b"));
    }

    public void test2() {
        assertEquals(":b", obj.op(null, "b"));
    }

    public void test3() {
        assertEquals("a:", obj.op("a", null));
    }

    public void test4() {
        assertEquals(":", obj.op(null, null));
    }

    public void test5() {
        // this will fail
        assertEquals(" : ", obj.op(null, null));
    }
}

Capturing basic information with a TestListener

JUnit3 allows listeners to be added their test processes. This listener is called before and after the test is run, plus anytime a test fails or has an error (throws an exception). This TestListener writes basic test information to System.out as a proof of concept. It would be easy to modify it to write the information to a database, a JMS topic, etc.

  1. public class SimpleTestListener implements TestListener {
  2.     private static final TimeZone UTC = TimeZone.getTimeZone("UTC");
  3.     private long start;
  4.     private boolean successful = true;
  5.     private String name;
  6.     private String failure = null;
  7.  
  8.     SimpleTestListener() {
  9.     }
  10.  
  11.     public void setName(String name) {
  12.         this.name = name;
  13.     }
  14.  
  15.     public void startTest(Test test) {
  16.         start = System.currentTimeMillis();
  17.     }
  18.  
  19.     public void addError(Test test, Throwable t) {
  20.         // cache information about error.
  21.         successful = false;
  22.     }
  23.  
  24.     public void addFailure(Test test, AssertionFailedError e) {
  25.         // cache information about failure.
  26.         failure = e.getMessage();
  27.         successful = false;
  28.     }
  29.  
  30.     /**
  31.      * After the test finishes we can update the database with statistics about
  32.      * the test - name, elapsed time, whether it was successful, etc.
  33.      */
  34.     public void endTest(Test test) {
  35.         long elapsed = System.currentTimeMillis() - start;
  36.  
  37.         SimpleDateFormat fmt = new SimpleDateFormat();
  38.         fmt.setTimeZone(UTC);
  39.  
  40.         System.out.printf("[%s, %s, %s, %d, %s, %s]\n", test.getClass().getName(), name, fmt.format(new Date(start)),
  41.                 elapsed, failure, Boolean.toString(successful));
  42.  
  43.         // write any information about errors or failures to database.
  44.     }
  45. }
public class SimpleTestListener implements TestListener {
    private static final TimeZone UTC = TimeZone.getTimeZone("UTC");
    private long start;
    private boolean successful = true;
    private String name;
    private String failure = null;

    SimpleTestListener() {
    }

    public void setName(String name) {
        this.name = name;
    }

    public void startTest(Test test) {
        start = System.currentTimeMillis();
    }

    public void addError(Test test, Throwable t) {
        // cache information about error.
        successful = false;
    }

    public void addFailure(Test test, AssertionFailedError e) {
        // cache information about failure.
        failure = e.getMessage();
        successful = false;
    }

    /**
     * After the test finishes we can update the database with statistics about
     * the test - name, elapsed time, whether it was successful, etc.
     */
    public void endTest(Test test) {
        long elapsed = System.currentTimeMillis() - start;

        SimpleDateFormat fmt = new SimpleDateFormat();
        fmt.setTimeZone(UTC);

        System.out.printf("[%s, %s, %s, %d, %s, %s]\n", test.getClass().getName(), name, fmt.format(new Date(start)),
                elapsed, failure, Boolean.toString(successful));

        // write any information about errors or failures to database.
    }
}

A production TestListener should do a lot more with errors and failures. I’ve skipped that in order to focus on the broader issues.

This listener is not thread-safe so we will want to use a Factory pattern to create a fresh instance for each test. We can create heavyweight objects in the factory, e.g., open a SQL DataSource in the factory and pass a fresh Connection to each instance.

  1. public class SimpleTestListenerFactory {
  2.     public static final SimpleTestListenerFactory INSTANCE = new SimpleTestListenerFactory();
  3.  
  4.     public SimpleTestListenerFactory() {
  5.         // establish connection data source here?
  6.     }
  7.  
  8.     public SimpleTestListener newInstance() {
  9.         // initialize listener.
  10.         SimpleTestListener listener = new SimpleTestListener();
  11.         return listener;
  12.     }
  13. }
public class SimpleTestListenerFactory {
    public static final SimpleTestListenerFactory INSTANCE = new SimpleTestListenerFactory();

    public SimpleTestListenerFactory() {
        // establish connection data source here?
    }

    public SimpleTestListener newInstance() {
        // initialize listener.
        SimpleTestListener listener = new SimpleTestListener();
        return listener;
    }
}

If we know the test framework is purely serial we can capture all console output by creating a buffer and calling System.setOut() in startTest() and then restoring the original System.out in endTest(). This works well as long as tests never overlap but will cause problems otherwise. This can be problematic though – IDEs may have their own test runners that allow concurrent execution.

We override the standard run() method with our own that creates and registers a listener before calling the existing run() method.

  1. public class SimpleTestCase extends TestCase {
  2.  
  3.     public void run(TestResult result) {
  4.         SimpleTestListener l = SimpleTestListenerFactory.INSTANCE.newInstance();
  5.         result.addListener(l);
  6.         l.setName(getName());
  7.         super.run(result);
  8.         result.removeListener(l);
  9.     }
  10. }
public class SimpleTestCase extends TestCase {

    public void run(TestResult result) {
        SimpleTestListener l = SimpleTestListenerFactory.INSTANCE.newInstance();
        result.addListener(l);
        l.setName(getName());
        super.run(result);
        result.removeListener(l);
    }
}

We now get the expected results to System.out.

  1. [MySimpleTest, test1, 8/2/15 11:58 PM, 0, null, true]
  2. [MySimpleTest, test2, 8/2/15 11:58 PM, 10, null, true]
  3. [MySimpleTest, test3, 8/2/15 11:58 PM, 0, null, true]
  4. [MySimpleTest, test4, 8/2/15 11:58 PM, 0, null, true]
  5. [MySimpleTest, test5, 8/2/15 11:58 PM, 4, expected same:<:> was not:< : >, false]
[MySimpleTest, test1, 8/2/15 11:58 PM, 0, null, true]
[MySimpleTest, test2, 8/2/15 11:58 PM, 10, null, true]
[MySimpleTest, test3, 8/2/15 11:58 PM, 0, null, true]
[MySimpleTest, test4, 8/2/15 11:58 PM, 0, null, true]
[MySimpleTest, test5, 8/2/15 11:58 PM, 4, expected same:<:> was not:< : >, false]

Capturing call information with a facade and TestListener

This is a good start but we might be able to do better. Only 4 methods are called in the thousands of tests mentioned above – it would be extremely powerful if we could capture the input and output values on those calls.

It is easy to wrap these functions with AOP, or a logging facade if AOP is not acceptable for some reason. In simple cases we can simply capture the input and output values.

  1. public class MyFacadeClass extends MyTestedClass {
  2.     private MyTestedClass parent;
  3.     private String a;
  4.     private String b;
  5.     private String result;
  6.  
  7.     public MyFacadeClass(MyTestedClass parent) {
  8.         this.parent = parent;
  9.     }
  10.  
  11.     public String getA() {
  12.         return a;
  13.     }
  14.  
  15.     public String getB() {
  16.         return b;
  17.     }
  18.  
  19.     public String getResult() {
  20.         return result;
  21.     }
  22.  
  23.     /**
  24.      * Wrap tested method so we can capture input and output.
  25.      */
  26.     public String op(String a, String b) {
  27.         this.a = a;
  28.         this.b = b;
  29.         String result = parent.op(a, b);
  30.         this.result = result;
  31.         return result;
  32.     }
  33. }
public class MyFacadeClass extends MyTestedClass {
    private MyTestedClass parent;
    private String a;
    private String b;
    private String result;

    public MyFacadeClass(MyTestedClass parent) {
        this.parent = parent;
    }

    public String getA() {
        return a;
    }

    public String getB() {
        return b;
    }

    public String getResult() {
        return result;
    }

    /**
     * Wrap tested method so we can capture input and output.
     */
    public String op(String a, String b) {
        this.a = a;
        this.b = b;
        String result = parent.op(a, b);
        this.result = result;
        return result;
    }
}

We log the basic information as before and add just a bit new code to log the inputs and outputs.

  1. public class AdvancedTestListener extends SimpleTestListener {
  2.  
  3.     AdvancedTestListener() {
  4.     }
  5.  
  6.     /**
  7.      * Log information as before but also log call details.
  8.      */
  9.     public void endTest(Test test) {
  10.         super.endTest(test);
  11.  
  12.         // add captured inputs and outputs
  13.         if (test instanceof MyAdvancedTest) {
  14.             MyTestedClass obj = ((MyAdvancedTest) test).obj;
  15.             if (obj instanceof MyFacadeClass) {
  16.                 MyFacadeClass facade = (MyFacadeClass) obj;
  17.                 System.out.printf("[, , %s, %s, %s]\n", facade.getA(), facade.getB(), facade.getResult());
  18.             }
  19.         }
  20.     }
  21. }
public class AdvancedTestListener extends SimpleTestListener {

    AdvancedTestListener() {
    }

    /**
     * Log information as before but also log call details.
     */
    public void endTest(Test test) {
        super.endTest(test);

        // add captured inputs and outputs
        if (test instanceof MyAdvancedTest) {
            MyTestedClass obj = ((MyAdvancedTest) test).obj;
            if (obj instanceof MyFacadeClass) {
                MyFacadeClass facade = (MyFacadeClass) obj;
                System.out.printf("[, , %s, %s, %s]\n", facade.getA(), facade.getB(), facade.getResult());
            }
        }
    }
}

The logs now show both the basic information and the call details.

  1. [MyAdvancedTest, test2, 8/3/15 12:13 AM, 33, null, true]
  2. [, , null, b, :b]
  3. [MyAdvancedTest, test3, 8/3/15 12:13 AM, 0, null, true]
  4. [, , a, null, a:]
  5. [MyAdvancedTest, test4, 8/3/15 12:13 AM, 0, null, true]
  6. [, , null, null, :]
  7. [MyAdvancedTest, test1, 8/3/15 12:13 AM, 0, null, true]
  8. [, , a, b, a:b]
[MyAdvancedTest, test2, 8/3/15 12:13 AM, 33, null, true]
[, , null, b, :b]
[MyAdvancedTest, test3, 8/3/15 12:13 AM, 0, null, true]
[, , a, null, a:]
[MyAdvancedTest, test4, 8/3/15 12:13 AM, 0, null, true]
[, , null, null, :]
[MyAdvancedTest, test1, 8/3/15 12:13 AM, 0, null, true]
[, , a, b, a:b]

We want to associate the basic and call details but that’s easily handled by adding a unique test id.

This approach is not enough in the real world where the tested methods may be called multiple times during a single test. In this case we need to either have a way to cache multiple sets of input and output values or to extend the listener so we can call it at the end of each covered method.

We can make our results more extensible by encoding the results in XML or JSON instead of a simple list. This will allow us to only capture values of interest or to easily handle fields added in the future.

  1. [MyAdvancedTest, test2, 8/3/15 12:13 AM, 33, null, true]
  2. {"a":null, "b":"b", "results":":b" }
  3. [MyAdvancedTest, test3, 8/3/15 12:13 AM, 0, null, true]
  4. {"a":"a", "b":null, "results":"a:" }
  5. [MyAdvancedTest, test4, 8/3/15 12:13 AM, 0, null, true]
  6. {"a":null, "b":null, "results":":" }
  7. [MyAdvancedTest, test1, 8/3/15 12:13 AM, 0, null, true]
  8. {"a":" a", "b":"b", "results":" a:b" }
[MyAdvancedTest, test2, 8/3/15 12:13 AM, 33, null, true]
{"a":null, "b":"b", "results":":b" }
[MyAdvancedTest, test3, 8/3/15 12:13 AM, 0, null, true]
{"a":"a", "b":null, "results":"a:" }
[MyAdvancedTest, test4, 8/3/15 12:13 AM, 0, null, true]
{"a":null, "b":null, "results":":" }
[MyAdvancedTest, test1, 8/3/15 12:13 AM, 0, null, true]
{"a":" a", "b":"b", "results":" a:b" }

Capturing assertX information

We can now rerun the tests by replaying the captured inputs but there are two problems with blindly comparing the results. First, it will be a lot of unnecessary work if we only care about a single value. Second, many tests are non-deterministic (e.g., they use canned data that changes over time or even live data) and things we don’t care about may change.

This is not an easy problem. If we’re lucky the tests will follow the standard pattern and we can make a good guess at what tests are being performed but it needs to be manually verified.

First, we need to wrap the tested method’s results with a facade that captures some or all method calls. The call history should become available in a form that we can replay later, e.g., a sequence of method names and serialized parameters.

Second, we need to wrap the TestCase assertX methods so that we capture the recent method calls and the values passed to the assert call (plus the results, of course).

Example

The process is easiest to show – and demolish – with an example. Let’s start with a simple POJO.

  1. public class Person {
  2.     private String firstName;
  3.     private String lastName;
  4.  
  5.     public String getFirstName() { return firstName; }
  6.     public String getLastName() { return lastName; }
  7. }
public class Person {
    private String firstName;
    private String lastName;

    public String getFirstName() { return firstName; }
    public String getLastName() { return lastName; }
}

In this case our facade only needs to record the method name.

A typical test method is

  1. public void test1() {
  2.     Person p = getTestPerson();
  3.     assertEquals("John", p.getFirstName());
  4.     assertEquals("Smith", p.getLastName());
  5. }
public void test1() {
    Person p = getTestPerson();
    assertEquals("John", p.getFirstName());
    assertEquals("Smith", p.getLastName());
}

with a wrapped assertX method of

  1. static PersonFacade person;
  2.  
  3. public static void assertEquals(String expected, String actual) {
  4.     // ignoring null handling...
  5.     boolean results = expected.equals(actual);
  6.     LOG.log("assertEquals('" + expected + "',"+person.getMethodsCalled()+ ") = " + results);
  7.     person.clearMethodsCalled();
  8.     if (!results) {
  9.         throw new AssertionFailedError("Expected same:<" + expected + " > was not:<" + actual + ">");
  10.     }
  11. }
static PersonFacade person;

public static void assertEquals(String expected, String actual) {
    // ignoring null handling...
    boolean results = expected.equals(actual);
    LOG.log("assertEquals('" + expected + "',"+person.getMethodsCalled()+ ") = " + results);
    person.clearMethodsCalled();
    if (!results) {
        throw new AssertionFailedError("Expected same:<" + expected + " > was not:<" + actual + ">");
    }
}

so we would get results like

  1. assertEquals('John', getFirstName()) = true;
  2. assertEquals('Smith', getLastName()) = false;
assertEquals('John', getFirstName()) = true;
assertEquals('Smith', getLastName()) = false;

It’s not hard to see how this could be parsed by a test framework but it’s too early to celebrate. The second test method is

  1. public void test1() {
  2.     Person p = getTestPerson();
  3.     assertEquals("john", p.getFirstName().toLowerCase());
  4. }
public void test1() {
    Person p = getTestPerson();
    assertEquals("john", p.getFirstName().toLowerCase());
}

and our simple code will not capture the toLowerCase(). Our log will wrongly record

  1. assertEquals('John', getFirstName()) = false;
assertEquals('John', getFirstName()) = false;

A more pathological case is

  1. public void test1() {
  2.     Person p = getTestPerson();
  3.     LOG.log("testing " + p.getFirstName());
  4.     assertEquals("john", "joe");
  5. }
public void test1() {
    Person p = getTestPerson();
    LOG.log("testing " + p.getFirstName());
    assertEquals("john", "joe");
}

where the assertion has nothing to do with the wrapped class.

There are obvious bandaids, e.g., we could capture the return values in our facade, but this is a very deep rabbit hole that we want to stay far away from. I think the answer is to make a reasonable first attempt, manually verify the results, and leave it at that. (Alternative: rewrite the tests to a form that can be captured.)

Categories
java
Comments rss
Comments rss
Trackback
Trackback

« Installing PostgreSQL PL/Java as a PostgreSQL Extension. Storing X.509 Digital Certificates (And Other Messy Things) »

Leave a Reply

Click here to cancel reply.

You must be logged in to post a comment.

Archives

  • May 2020 (1)
  • March 2019 (1)
  • August 2018 (1)
  • May 2018 (1)
  • February 2018 (1)
  • November 2017 (4)
  • January 2017 (3)
  • June 2016 (1)
  • May 2016 (1)
  • April 2016 (2)
  • March 2016 (1)
  • February 2016 (3)
  • January 2016 (6)
  • December 2015 (2)
  • November 2015 (3)
  • October 2015 (2)
  • August 2015 (4)
  • July 2015 (2)
  • June 2015 (2)
  • January 2015 (1)
  • December 2014 (6)
  • October 2014 (1)
  • September 2014 (2)
  • August 2014 (1)
  • July 2014 (1)
  • June 2014 (2)
  • May 2014 (2)
  • April 2014 (1)
  • March 2014 (1)
  • February 2014 (3)
  • January 2014 (6)
  • December 2013 (13)
  • November 2013 (6)
  • October 2013 (3)
  • September 2013 (2)
  • August 2013 (5)
  • June 2013 (1)
  • May 2013 (2)
  • March 2013 (1)
  • November 2012 (1)
  • October 2012 (3)
  • September 2012 (2)
  • May 2012 (6)
  • January 2012 (2)
  • December 2011 (12)
  • July 2011 (1)
  • June 2011 (2)
  • May 2011 (5)
  • April 2011 (6)
  • March 2011 (4)
  • February 2011 (3)
  • October 2010 (6)
  • September 2010 (8)

Recent Posts

  • 8-bit Breadboard Computer: Good Encapsulation!
  • Where are all the posts?
  • Better Ad Blocking Through Pi-Hole and Local Caching
  • The difference between APIs and SPIs
  • Hadoop: User Impersonation with Kerberos Authentication

Meta

  • Log in
  • Entries RSS
  • Comments RSS
  • WordPress.org

Pages

  • About Me
  • Notebook: Common XML Tasks
  • Notebook: Database/Webapp Security
  • Notebook: Development Tips

Syndication

Java Code Geeks

Know Your Rights

Support Bloggers' Rights
Demand Your dotRIGHTS

Security

  • Dark Reading
  • Krebs On Security Krebs On Security
  • Naked Security Naked Security
  • Schneier on Security Schneier on Security
  • TaoSecurity TaoSecurity

Politics

  • ACLU ACLU
  • EFF EFF

News

  • Ars technica Ars technica
  • Kevin Drum at Mother Jones Kevin Drum at Mother Jones
  • Raw Story Raw Story
  • Tech Dirt Tech Dirt
  • Vice Vice

Spam Blocked

53,793 spam blocked by Akismet
rss Comments rss valid xhtml 1.1 design by jide powered by Wordpress get firefox