How can I test with junit that a warning was logged with log4j?

Question

I'm testing a method that logs warnings when something went wrong and returns null.
something like:

private static final Logger log = Logger.getLogger(Clazz.class.getName());
....
if (file == null || !file.exists()) {
  // if File not found
  log.warn("File not found: "+file.toString());
} else if (!file.canWrite()) {
  // if file is read only
  log.warn("File is read-only: "+file.toString());
} else {
  // all checks passed, can return an working file.
  return file;
}
return null;

i'd like to test with junit that a warning was issued, in addition to returning null, in all cases (e.g. file not found, file is read-only).
any ideas?
thanks, asaf :-)

---

UPDATE

My implementation of Aaron's answer (plus peter's remark):

public class UnitTest {
...

@BeforeClass
public static void setUpOnce() {
  appenders = new Vector<Appender>(2);
  // 1. just a printout appender:
  appenders.add(new ConsoleAppender(new PatternLayout("%d [%t] %-5p %c - %m%n")));
  // 2. the appender to test against:
  writer = new StringWriter();
  appenders.add(new WriterAppender(new PatternLayout("%p, %m%n"),writer));
}

@Before
public void setUp() {
  // Unit Under Test:
  unit = new TestUnit();
  // setting test appenders:
  for (Appender appender : appenders) {
    TestUnit.log.addAppender(appender);
  }
  // saving additivity and turning it off:
  additivity = TestUnit.log.getAdditivity();
  TestUnit.log.setAdditivity(false);
}

@After
public void tearDown() {
  unit = null;
  for (Appender appender : appenders) {
    TestUnit.log.removeAppender(appender);
  }
  TestUnit.log.setAdditivity(additivity);
}

@Test
public void testGetFile() {
  // start fresh:
  File file;
  writer.getBuffer().setLength(0);

  // 1. test null file:
  System.out.println(" 1. test null file.");
  file = unit.getFile(null);
  assertNull(file);
  assertTrue(writer.toString(), writer.toString().startsWith("WARN, File not found"));
  writer.getBuffer().setLength(0);

  // 2. test empty file:
  System.out.println(" 2. test empty file.");
  file = unit.getFile("");
  assertNull(file);
  assertTrue(writer.toString(), writer.toString().startsWith("WARN, File not found"));
  writer.getBuffer().setLength(0);
}

thanks guys,

Answer 1

In the setup of the unit test:

1. Get the same logger
2. Make it non-additive

3. Add an appender which remembers the messages in a list:

   public class TestAppender extends AppenderSkeleton {
       public List<String> messages = new ArrayList<String>();
   
       public void doAppend(LoggingEvent event) {
           messages.add( event.getMessage().toString() );
       }
   }
   

4. Add the appender to the logger

Now you can call your code. After the test, you will find all log messages in the list. Add the log level if you want (messages.add( event.getLevel() + " " + event.getMessage() );).

In tearDown(), remove the appender again and enable additivity.

Answer 2

Using Mockito you can test the logging that occurred during your test with minimal boiler plate code, a simple example is:

@RunWith(MockitoJUnitRunner.class)
public class TestLogging {

  @Mock AppenderSkeleton appender;
  @Captor ArgumentCaptor<LoggingEvent> logCaptor;


  @Test
  public void test() {
    Logger.getRootLogger().addAppender(appender);

    ...<your test code here>...

    verify(appender).doAppend(logCaptor.capture());
    assertEquals("Warning message should have been logged", "Caution!", logCaptor.getValue().getRenderedMessage());
  }
}

Answer 3

The examples in this post were very helpful, but I found them little confusing.
So I am adding a simplified version for the above with some minor changes.

• I am adding my appender to the root logger.

This way, and assuming additively is true by default, I will not need to worry about losing my events due to logger hierarchy. Make sure this meet your log4j.properties file configuration.

• I am overriding append and not doAppend.

Append in AppenderSkeleton deals with level filtering, so I do not want to miss that.
doAppend will call append if the level is right.

public class TestLogger {
    @Test
    public void test() {
        TestAppender testAppender = new TestAppender();

        Logger.getRootLogger().addAppender(testAppender);
        ClassUnderTest.logMessage();
        LoggingEvent loggingEvent = testAppender.events.get(0);
        //asset equals 1 because log level is info, change it to debug and 
        //the test will fail
        assertTrue("Unexpected empty log",testAppender.events.size()==1);               
        assertEquals("Unexpected log level",Level.INFO,loggingEvent.getLevel());
        assertEquals("Unexpected log message"
                        ,loggingEvent.getMessage().toString()
                        ,"Hello Test");
    }

    public static class TestAppender extends AppenderSkeleton{
        public List<LoggingEvent> events = new ArrayList<LoggingEvent>();
        public void close() {}
        public boolean requiresLayout() {return false;}
        @Override
        protected void append(LoggingEvent event) {
                      events.add(event);
          }     
    }

    public static class ClassUnderTest {
        private static final Logger LOGGER = 
            Logger.getLogger(ClassUnderTest.class);
        public static void logMessage(){
          LOGGER.info("Hello Test");
          LOGGER.debug("Hello Test");
        }
    }
}

log4j.properties

log4j.rootCategory=INFO, CONSOLE
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%d %p  [%c] - %m%n
# un-comment this will fail the test   
#log4j.logger.com.haim.logging=DEBUG

Answer 4

An alternative to Aaron's solution would be to configure a WriterAppender with an attached StringWriter. At the end of the test, you can verify the contents of the log output string.

This is a bit easier to implement (no need for custom code), however is less flexible with regards to checking the results, as you only get the output as plain text. In some cases that may make it more difficult to verify the output than with Aaron's solution.

Answer 5

Instead of calling log4j directly, use a protected method in your class.

Something like:

protected void log(String message, Level level)
{
    //delegates to log4j
}

Then create a subclass of the class under test that oevrrides this method, so that you can verify it is being called as expected.

class MyTest extends <class under test>
{
    boolean somethingLogged = false;
    protected void log(String message, Level level)
    {
        somethingLogged = true;
    }
}

and then assert based on somethingLogged. You can add conditional logic in the overriding method t test based on expected message/level.

You could go further and record all the invocations, and then search through the logged messages, or check they were logged in the right order etc...

Answer 6

I'm adapting Haim's answer to something that's more RAII:

public static class TestAppender extends AppenderSkeleton {
    @Override
    protected void append(LoggingEvent event) {
        messages.add(event.getRenderedMessage());
    }

    @Override
    public void close() { }

    @Override
    public boolean requiresLayout() { return false; }

    protected final List<String> messages = new ArrayList<>();
}

static class LogGuard implements AutoCloseable {
    protected final TestAppender appender;

    LogGuard(Level level) {
        appender = new TestAppender();
        appender.setThreshold(level);
        Logger.getRootLogger().addAppender(appender);
    }

    @Override
    public void close() throws Exception {
        Logger.getRootLogger().removeAppender(appender);
    }
}

And then the usage is simply:

try (LogGuard log = new LogGuard(Level.WARN)) { // if you want WARN or higher
    // do what causes the logging
   Assert.assertTrue(log.appender.messages.stream().anyMatch(m -> m.equals("expected"));
}