Can I automatically execute JUnit testcases once with all logging enabled and once with all logging disabled?

Question

I've found a solution, see my own answer below. Does anyone have a more elegant one?

I want to do this to increase code-coverage and find subtle bugs.

Assume the following class to be tested:

public class Foo {
    private final Logger logger = LoggerFactory.getLogger(Foo.class);
    public void bar() {
        String param=[..];
        if(logger.isInfoEnabled()) logger.info("A message with parameter {}", param);

        if(logger.isDebugEnabled()) {
            // some complicated preparation for the debug message
            logger.debug([the debug message]);
        }
    }
}

and the following test-class:

public class FooTest {
    @Test
    public void bar() {
        Foo foo=new Foo();
        foo.bar();
    }
}

A code-coverage tool like e.g. Cobertura will correctly report that only some of the conditional branches have been checked.

info and debug are either activated or deactivated for the logger.

Besides looking bad in your coverage score, this poses a real risk.

What if there is some side effect caused by code inside if(logger.isDebugEnabled())? What if your code does only work if DEBUG is enabled and fails miserably if the log level is set to INFO? (This actually happened in one of our projects :p)

So my conclusion is that code containing logger statements should always be tested once with all logging enabled and once with all logging disabled...

Is there a way to do something like that with JUnit? I know how to globally enable or disable all my logging in Logback so the problem is: How can I execute the tests twice, once with logging enabled, once with logging disabled.

p.s. I'm aware of this question but I don't think this is a duplicate. I'm less concerned about the absolute coverage values but about subtle, hard-to-find bugs that might be contained inside of a if(logger.isDebugEnabled()).

Cask

Answer 1

I've solved this problem by implementing a base class that test classes should extend if such functionality is desired.

The article Writing a parameterized JUnit test contained the solution.

See LoggingTestBase for the logging base class and LoggingTestBaseExampleTest for a simple example that's using it.

Every contained test method is executed three times:

1. It's executed using the logging as defined in logback-test.xml as usual. This is supposed to help while writing/debugging the tests.

2. It's executed with all logging enabled and written to a file. This file is deleted after the test.

3. It's executed with all logging disabled.

Yes, LoggingTestBase needs documentation ;)

Cask

Note, it is not considered good practice to manage log levels for a typical application by writing out the configuration from the application. Logging frameworks are designed to manage this external to the application. – Bigamy

They are unit-tests, it's not an application. Also, there are certainly cases were changing the loog-level configuration makes sense, e.g. a '-v' commandline option of a console application. – Cask

You could configure logback programmatically without Joran. You'd have shorter code. Moreover, if configuration were done programmaticaly, you could restore the old configuration at the end of each test. Holler on logback-dev if you'd like to see sample code. Otherwise, very nice work! – Delanty

Thanks, I'll come back at you on the dev list. I wasn't aware that logback can be configured programmatically, Joran aside, and that configuration can be restored beside reconfiguration. – Cask

Answer 2

Have you tried simply maintaining two separate log configuration files? Each one would log at different levels from the root logger.

All logging disabled:

...
<root>
    <priority value="OFF"/>
    <appender-ref ref="LOCAL_CONSOLE"/>
</root>
...

All logging enabled:

...
<root>
    <priority value="ALL"/>
    <appender-ref ref="LOCAL_CONSOLE"/>
</root>
...

Execution would specify different configurations on the classpath via a system parameter:

-Dlog4j.configuration=path/to/logging-off.xml
-Dlog4j.configuration=path/to/logging-on.xml

Bigamy

I was thinking more in the lines of Maven 2 and Logback. Having two configs and initializing the logging framework isn't the problem. Executing the tests twice calling the respective logger configuration method beforehand is my problem. I should have stated that more clearly, I think. – Cask

you can specify system parameters in maven in a choosable profile. You want two profiles, one with logging and one without. Getting them to both execute with one command is beyond my ken – Suzy

@Huxi: note, the log configuration file is not just for initializing the logging framework, it's used for controlling the log levels (which is what you're trying to do). By doing two (or three) test runs, you're accomplishing what you want without forcing developers to create 3 unit tests for this functionality (which is what you're proposing). You can control which log configuration is chosen by each run using different maven profiles. A script can take care of executing the runs in one command. – Bigamy

I'd like to be able to simply execute 'mvn clean install' and have all tests executed. With my solution proposal in my own answer this is possible. Additionally, the developer is only required to write a single, ordinary test class as usual. – Cask

Answer 3

I would recommend switching from JUnit to TestNG. TestNG has a lot of advanced features over JUnit. It enables you to run your tests multiple times with different configuration and I guess that's what you need

Tifanytiff

Can JUnit and TestNG be combined? I'm more or less talking about Maven 2 integration here... all our tests are JUnit tests... – Cask

Yes, TestNG can run JUnit tests. I use it in maven2 projects all the time – Tifanytiff

Converting a test from TestNG to JUnit is easy, though time-consumnig – Tifanytiff

Answer 4

eqbridges suggestion of simply running the tests twice with different logging contexts seems the simplest. You don't have to remember to code the logic in every blessed test, for one big advantage. The other is that you can see which logging level is to blame very easily.

That being said, there a couple of strategies if you just had to do this in one test run.

For 3.8 I would put everything in suites, and make two suites, one for each logging level, which sets the logging level before running the tests. This is functionally the same thing as running the whole test suite twice with different command line parameters, except that you get it with one run.

In JUnit 4.x a couple of additional options come to mind:

One is a custom runner. Although I can't think off hand of everything you would have to do to make this work, but a runner that actually runs the test twice and annotating the test with @RunWith your custom runner could work.

The other is parameterized tests. Although you would actually have to set up every test to take parameters (this requires a constructor which takes the arguments) and then set the log level according to the parameter.

EDIT: In response to your request for a how-to on the paramterized tests, here is the javadoc on the runner to get you started, and here is a more practical guide.

Swansea

Do you have any links to docu about parameterized tests? The JUnit FAQ was last updated in 2006 and I couldn't find anything like it... What's going on at junit.org?? The cookbook seems to be outdated, too... – Cask

Thanks for the "parameterized tests" hint. I found some documentation, see my solution. – Cask

Answer 5

If you feel you have too much logging if you turn everything on, perhaps you could try to cut down the amount of logging. Its not very useful if it too much for the computer to procude never mind a human to read.

Blau

I route all logging into a temp file so the output isn't cluttered with useless logging messages. The whole point of my question is that I'd like to be able to test both scenarios: all logging turned on and all logging turned off. We really had the situation that a class would work if run with debug enabled and wouldn't with only info enabled. I'd like to catch such problems in a general way. – Cask