Looking for problematic logging with JUnit

Stefan Birkner's System Rules is one of my favorite JUnit extension libraries. I commonly use it to verify System.out and System.err, for example validating audit trail logging.

Growing tired of the same boilerplate, I rolled some simple rules into an aggregated JUnit @Rule, called NiceLoggingRule. It enforces:

• No logging to System.err
• No WARN or ERROR logging to System.out

A more sophisticated version would let the user decide on more than "log level" as to what is an acceptable log line, but it gives a good demonstration of writing complex JUnit rules:

public final class NiceLoggingRule
        implements TestRule {
    private static final Pattern NEWLINE = compile("\n");

    private final SystemOutRule sout = new SystemOutRule().
            enableLog().
            muteForSuccessfulTests();
    private final SystemErrRule serr = new SystemErrRule().
            enableLog();

    private final Pattern logLinePattern;
    private final Predicate<String> problematic;
    private final RuleChain delegate;

    public NiceLoggingRule(final String logLinePattern,
            final Predicate<String> problematic) {
        this.logLinePattern = compile(logLinePattern);
        this.problematic = problematic;
        delegate = outerRule(NiceLoggingStatement::new).
                around(sout).
                around(serr);
    }

    @Override
    public Statement apply(final Statement base,
            final Description description) {
        return delegate.apply(base, description);
    }

    private final class NiceLoggingStatement
            extends Statement {
        private final Statement base;
        private final Description description;

        private NiceLoggingStatement(final Statement base,
                final Description description) {
            this.base = base;
            this.description = description;
        }

        @Override
        public void evaluate()
                throws Throwable {
            base.evaluate();
            checkSystemErr(description);
            checkSystemOut(description);
        }

        private void checkSystemErr(final Description description) {
            final String cleanSerr = serr.getLogWithNormalizedLineSeparator();
            final List<String> errors = NEWLINE.splitAsStream(cleanSerr).
                    collect(toList());
            if (!errors.isEmpty())
                fail("Output to System.err from " + description + ":\n"
                        + cleanSerr);
        }

        private void checkSystemOut(final Description description) {
            final String cleanSout = sout.getLogWithNormalizedLineSeparator();
            final List<LogLine> problems = NEWLINE.splitAsStream(cleanSout).
                    map(LogLine::new).
                    filter(LogLine::problematic).
                    collect(toList());
            if (!problems.isEmpty())
                fail(problems.stream().
                        map(Object::toString).
                        collect(joining("",
                                "Problems to System.out from " + description
                                        + ":\n", "")));
        }
    }

    private final class LogLine {
        @Nonnull
        private final String line;
        @Nonnull
        private final String level;

        private LogLine(@Nonnull final String line) {
            final Matcher match = logLinePattern.matcher(line);
            if (!match.find()) // Not match! Ignore trailing CR?NL
                fail(format(
                        "Log line does not match expected pattern (%s): %s",
                        logLinePattern.pattern(), line));
            this.line = line;
            level = match.group("level");
        }

        public boolean problematic() {
            return problematic.test(level);
        }

        @Override
        public String toString() {
            return line;
        }
    }
}

For example, using it with Spring Boot's default log pattern one might write a factory helper:

public final class SpringDefaultNiceLoggingRule {
    private static final String logLevels = Stream.of(LogLevel.values()).
            filter(level -> OFF != level).
            map(Enum::name).
            collect(joining("|"));

    public static NiceLoggingRule springDefaultNiceLoggingRule() {
        return new NiceLoggingRule(
                "^(?<timestamp>\\d{4,4}-\\d{2,2}-\\d{2,2} \\d{2,2}:\\d{2,2}:\\d{2,2}\\.\\d{3,3}) +(?<level>"
                        + logLevels + ") +",
                SpringDefaultNiceLoggingRule::problematic);
    }

    private static boolean problematic(final String level) {
        return 0 > INFO.compareTo(LogLevel.valueOf(level));
    }
}

Then a simple Spring Boot unit test becomes:

@RunWith(SpringJUnit4ClassRunner.class)
@SpringApplicationConfiguration(classes = MockServletContext.class)
public final class RootControllerTest {
    @Rule
    public final NiceLoggingRule niceLogging = springDefaultNiceLoggingRule();

    private MockMvc mvc;

    @Before
    public void setUp()
            throws Exception {
        mvc = standaloneSetup(new RootController()).build();
    }

    @Test
    public void shouldGetRoot()
            throws Exception {
        mvc.perform(get("/").
                accept(APPLICATION_JSON_UTF8)).
                andExpect(status().isOk()).
                andExpect(jsonPath("$.message", equalTo("Hello, world!")));
    }
}

The JUnit forest

Edmund Kirwan damns the ubiquitous JUnit in JUnit's evolving structure. What's the problem? — galloping interdependencies. As a bonus, a spiffy graphical timeline of JUnit's structure.

JUnit testing that a call blocks

Certain that I missed an existing solution, I post this in hopes of helping anyone who also misses it. But if you know a better way, please comment.

Usage

class SomeTest {
    @Test(timeout = 1000L)
    public void shouldBlock() {
        assertBlocks(new BlockingCall() {
            @Override
            public void call()
                    throws InterruptedException {
                // My blocking code here
            }
        });
    }
}

Implementation

import javax.annotation.Nonnull;
import java.util.Timer;
import java.util.TimerTask;

import static java.lang.String.format;
import static java.lang.Thread.currentThread;
import static org.junit.Assert.fail;

/**
 * {@code BlockingCall} supports blocking call assertion for JUnit tests.
 *
 * @author <a href="mailto:binkley@alumni.rice.edu">B. K. Oxley (binkley)</a>
 */
public interface BlockingCall {
    /**
     * Calls blocking code.  The blocking code must throw {@code
     * InterruptedException} when its current thread is interrupted.
     *
     * @throws InterruptedException if interrupted.
     */
    void call()
            throws InterruptedException;

    /** Wrapper class for block assertion. */
    public static final class Assert {
        /**
         * Asserts the given <var>code</var> blocks at least 100ms.  Interrupts
         * the blocking code after 100ms and checks {@code InterruptedException}
         * was thrown.  When not blocking, appends <var>block</var> to the
         * failure message.
         *
         * @param block the blocking call, never missing
         */
        public static void assertBlocks(@Nonnull final BlockingCall block) {
            final Timer timer = new Timer(true);
            try {
                final Thread current = currentThread();
                timer.schedule(new TimerTask() {
                    @Override
                    public void run() {
                        current.interrupt();
                    }
                }, 100L);
                block.call();
                fail(format("Did not block: %s", block));
            } catch (final InterruptedException ignored) {
            } finally {
                timer.cancel();
            }
        }
    }
}

UPDATE: Idioms like this would be far more attractive with Java 8 lambdas:

public void shouldBlock() {
    assertBlocks(() -> { /* blocking code */ });
}

Showing test failure name for JUnit parameterized tests

A popular complaint against JUnit is lack of human-readable names for parameterized test cases. There are several solutions, this is mine.

/**
 * {@code ParameterizedTest} simplifies parametered JUnit tests by including a "case label" to
 * identify the failing branch.  (JUnit only provides an index).  The failure message format
 * becomes "descriptive string from JUnit: case label: assertion failure message".
 * <p/>
 * Fully preserves the stack trace of failing tests.
 * <p/>
 * Example: <pre>
 * public class MyTest {
 *     &#64;Parameters
 *     public static Collection<Object[]> parameters() {
 *         return ...; // See JUnit documentation for parameterized tests
 *     }
 *
 *     public MyTest(final String caseLabel, final X x, final Y y) {
 *         super(caseLabel);
 *         this.x = x;
 *         this.y = y;
 *     }
 *
 *     &#64;Test
 *     public void shouldWork() {
 *         // Body of test method ...
 *     }
 * }
 * </pre>
 * When {@code shouldWork()} fails the failure message is more meaningful, including the
 * {@link #caseLabel "case label"} in the JUnit error message.
 *
 * @author <a href="mailto:binkley@alumni.rice.edu">B. K. Oxley (binkley)</a>
 */
@RunWith(Parameterized.class)
public abstract class ParameterizedTest {
    private final String caseLabel;

    /**
     * The JUnit test rule (test extension) which fails bad parameterized cases but provides a
     * {@link #caseLabel case label} identifing the failed test branch.
     */
    @Rule
    public final TestRule parameterizedTestRule = new TestWatcher() {
        @Override
        protected void failed(final Throwable e, final Description description) {
            final AssertionError x = new AssertionError(
                    description.getDisplayName() + ": " + caseLabel + ": " + e.getMessage());
            x.setStackTrace(e.getStackTrace());
            throw x;
        }
    };

    /**
     * Constructs a new {@code ParameterizedTest} for the given <var>caseLabel</var>.
     *
     * @param caseLabel the case label, never missing
     */
    protected ParameterizedTest(@Nonnull final String caseLabel) {
        this.caseLabel = caseLabel;
    }
}