Testing and Handling Logging in Java

Logging — which was added to Java 1.4 — allows you to add a filter. With that filter you can intercept and decide which logs to actually log.
Also, you have to make sure to use the same logger as the one you want to suppress. Just use the same string as identifier for both. I usually use the name of the class from the class object itself.
[code language=”java”]
Logger LOG = Logger.getLogger(Example.class.getName());
[/code]
once you have the logger instance, you add a filter which deals with the log record and suppresses its logging.
[code language=”java”]
logger.setFilter(new Filter()
{
public boolean isLoggable(LogRecord logRecord) {
if (logRecord.getLevel().intValue() == Level.SEVERE.intValue()) {
// deal with log record
}
return false; // suppress logging }
});
[/code]
Here the code for a small Example
[code language=”java”]
public class Example {
private static final Logger LOG = Logger.getLogger(Example.class.getName());
public void foo() {
LOG.info("entering");
try {
willFail();
} catch (Exception e) {
LOG.logp(Level.SEVERE, Example.class.getName(),
"foo", "something bad happened", e);
}
LOG.info("exiting");
}
private void willFail() throws Exception {
throw new Exception("ERROR MSG");
}
}
[/code]
And here the matching test
[code language=”java”]
public class ExamleTest extends TestCase {
private Example example;
private Logger logger;
private List logRecords;

protected void setUp() throws Exception {
example = new Example();
logger = Logger.getLogger(Example.class.getName());
logRecords = new ArrayList();
}

public void testFooLogsSevereIfFailure() {
logger.setFilter(new Filter()
{
public boolean isLoggable(LogRecord logRecord) {
if (logRecord.getLevel().intValue() == Level.SEVERE.intValue()) {
logRecords.add(logRecord);
}
return false;
}});

example.foo();

assertEquals(1, logRecords.size());
assertEquals("something bad happened", logRecords.get(0).getMessage());
assertEquals("ERROR MSG", logRecords.get(0).getThrown().getMessage());
}

public void testFooLogsEntryAndExit() {
logger.setFilter(new Filter()
{
public boolean isLoggable(LogRecord logRecord) {
if (logRecord.getLevel().intValue() == Level.INFO.intValue()) {
logRecords.add(logRecord);
}
return false;
}});

example.foo();

assertEquals(2, logRecords.size());
assertEquals("entering", logRecords.get(0).getMessage());
assertEquals("exiting", logRecords.get(1).getMessage());
}
}
[/code]
With this you remove the noise from running your tests as this
[code language=”java”]
ExamleTest,testFooLogsSevereIfFailure
May 5, 2008 9:50:18 PM Example foo
INFO: entering
May 5, 2008 9:50:18 PM Example foo
SEVERE: something bad happened
java.lang.Exception: ERROR MSG
at Example.willFail(Example.java:20)
at Example.foo(Example.java:11)
at ExamleTest.testFooLogsSevereIfFailure(ExamleTest.java:33)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at junit.framework.TestCase.runTest(TestCase.java:164)
at junit.framework.TestCase.runBare(TestCase.java:130)
at junit.framework.TestResult$1.protect(TestResult.java:106)
at junit.framework.TestResult.runProtected(TestResult.java:124)
at junit.framework.TestResult.run(TestResult.java:109)
at junit.framework.TestCase.run(TestCase.java:120)
at junit.textui.TestRunner.doRun(TestRunner.java:121)
at com.intellij.rt.execution.junit.IdeaTestRunner.doRun(IdeaTestRunner.java:65)
at junit.textui.TestRunner.doRun(TestRunner.java:114)
at com.intellij.rt.execution.junit.IdeaTestRunner.startRunnerWithArgs(IdeaTestRunner.java:24)
at com.intellij.rt.execution.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:118)
at com.intellij.rt.execution.junit.JUnitStarter.main(JUnitStarter.java:40)
May 5, 2008 9:50:18 PM Example foo
INFO: exiting

Process finished with exit code 0
[/code]
becomes that
[code language=”java”]
Process finished with exit code 0
[/code]