Sunday, April 21, 2013

Fault injection in your JUnit with ByteMan

This article shows how to use ByteMan from JBoss to inject fault when testing Java code.

As usual, let us start with some trivial code to test: a simple class that appends strings to a given file.
package org.javabenchmark.byteman;

import java.io.File;
import java.io.FileOutputStream;
import java.io.IOException;
import java.util.logging.Level;
import java.util.logging.Logger;

/**
 * Logging helper class.
 *
 */
public class LogHelper {

    public static final String LOG_FILE_PROPERTY = "logHelperFile";
    public static final String DEFAULT_LOG_FILE = "sample.log";
    private static final File LOG_FILE = new File(System.getProperty(LOG_FILE_PROPERTY, DEFAULT_LOG_FILE));

    /**
     * logs the given trace to a dedicated file.
     *
     * @param trace a string to be written into the log file.
     */
    public static void log(String trace) {

        try {
            FileOutputStream fos = new FileOutputStream(LOG_FILE, true);
            fos.write(trace.getBytes());
            fos.write('\n');
            fos.flush();
            fos.close();
        } catch (IOException ex) {
            final String msg = "Log Helper can't write trace to the log file: " + LOG_FILE.getAbsolutePath();
            System.err.println(msg);
        }
    }
}


The next step is to write the corresponding test:
package org.javabenchmark.byteman;

import java.io.File;
import static org.fest.assertions.api.Assertions.*;
import org.jboss.byteman.contrib.bmunit.BMRule;
import org.jboss.byteman.contrib.bmunit.BMUnitRunner;
import org.junit.Test;
import org.junit.runner.RunWith;

/**
 * Unit Test dedicated to LogHelper.
 */
public class LogHelperTest {

    private static final String SUCCESSFULL_TEST_LABEL = "Successfull Test";

    private void deleteFile(File file) {
        // clean
        file.delete();
        assertThat(file).doesNotExist();
    }
    
    @Test
    public void shouldLog() {

        File logFile = new File(LogHelper.DEFAULT_LOG_FILE);

        // clean
        deleteFile(logFile);

        // one line test
        LogHelper.log(SUCCESSFULL_TEST_LABEL);

        // control
        assertThat(logFile).exists();
        assertThat(logFile).hasContent(SUCCESSFULL_TEST_LABEL);

        // several lines test
        LogHelper.log(SUCCESSFULL_TEST_LABEL);
        LogHelper.log(SUCCESSFULL_TEST_LABEL);

        // control
        assertThat(logFile).hasContent(SUCCESSFULL_TEST_LABEL + '\n' + SUCCESSFULL_TEST_LABEL + '\n' + SUCCESSFULL_TEST_LABEL);
        deleteFile(logFile);
    }
}

Running the test produces the following output:
Testsuite: org.javabenchmark.byteman.LogHelperTest
Tests run: 1, Failures: 0, Errors: 0, Time elapsed: 0.136 sec

And if you enable code coverage in your favorite IDE, you should have something like this:

Red regions show us parts of the code that are not covered by the test. In our case, we can see that the code that handles IO exception is never invoked. Then, it is not possible to cover all the code of the method without raising an IOException. Hopefully, there is a powerful tool for this: ByteMan.

As explained by the authors:
Byteman is a tool which simplifies tracing and testing of Java programs. Byteman allows you to insert extra Java code into your application, either as it is loaded during JVM startup or even after it has already started running.

Actually, ByteMan is a java agent that does instrumentation and we are going to use it to inject IO exception during the execution of our test to check the code that deals with it. The idea is to throw an IOException when the method FileOutputStream.write(byte[]) is called.

Firstly, the dependency for ByteMan:

  org.jboss.byteman
  byteman-bmunit
  2.1.2


Secondly, modify the previous test to add ByteMan to our JUnit and write a new method to test the code that handles IOException:
package org.javabenchmark.byteman;

import java.io.File;
import static org.fest.assertions.api.Assertions.*;
import org.jboss.byteman.contrib.bmunit.BMRule;
import org.jboss.byteman.contrib.bmunit.BMUnitRunner;
import org.junit.Test;
import org.junit.runner.RunWith;

/**
 * Unit Test dedicated to LogHelper.
 */
@RunWith(BMUnitRunner.class)
public class LogHelperTest {

    private static final String SUCCESSFULL_TEST_LABEL = "Successfull Test";

    private void deleteFile(File file) {
        // ...
    }
    
    @Test
    public void shouldLog() {
        // ...
    }

    @Test
    @BMRule(name = "IOException Rule",
            targetClass = "FileOutputStream",
            targetMethod = "write(byte[])",
            targetLocation = "AT ENTRY",
            condition = "TRUE",
            action = "throw new java.io.IOException()")
    public void shouldHandleIOException() {
        
        File logFile = new File(LogHelper.DEFAULT_LOG_FILE);

        // clean
        deleteFile(logFile);

        // one line test that should raise an io exception
        LogHelper.log(SUCCESSFULL_TEST_LABEL);
        
        // control
        assertThat(logFile).exists();
        assertThat(logFile).hasContent("");
        
        // clean
        deleteFile(logFile);
    }
}


The BMRule annotation defines the execution context for ByteMan:
  • name: to set the name of the rule
  • targetClass and targetMethod: to set the method that must be instrumented
  • targetLocation: to set when to inject  the code (at the beginning, at the end or somewhere in the body of the method)
  • condition: to set some condition to be met
  • action: the code to be injected
So, we have a rule named "IOException Rule" that is activated when the method write(byte[]) of the FileOutputStream class begins. The rule then injects a given code that throws an IOException. When the shouldHandleIOException test runs, every time that write(byte[]) is called then a java.io.IOException is raised.

Now, running all tests produces:
Testsuite: org.javabenchmark.byteman.LogHelperTest
byteman jar is /home/javabenchmark/.m2/repository/org/jboss/byteman/byteman/2.1.2/byteman-2.1.2.jar
Log Helper can't write trace to the log file: /home/javabenchmark/Documents/projects/javabenchmark/sample.log
Tests run: 2, Failures: 0, Errors: 0, Time elapsed: 0.534 sec

And the code coverage looks like this:

The log(String) method is now fully covered (the implicit constructor of the LogHelper class is not tested, explaining the missing percents to reach 100%).

Conclusion

ByteMan is very useful to test code that deals with Exception, especially fault tolerant one. That way, you can check that your fault tolerance strategy is really resilient, or that your code gives you relevant traces when errors occur.

3 comments:

  1. Interesting. Of course you could test such code without ByteMan but you would have to introduce changes into the source code (some for of DI or extract method etc).

    ReplyDelete
  2. And if I'm not using JUnit would it be possible to use ByteMan programmaticaly (without specific JUnit runner) in my tests? Could you provide some code example?

    ReplyDelete
    Replies
    1. Tomek, thanks for your comments ! About using ByteMan programmatically, i would suggest to have a look at the code of the BMUnit class, which is responsible of loading the ByteMan agent : http://grepcode.com/file/repo1.maven.org/maven2/org.jboss.byteman/byteman-bmunit/2.1.2/org/jboss/byteman/contrib/bmunit/BMUnit.java#BMUnit.loadAgent%28%29 (i like the trick to find the VM that runs the current code).

      Delete