Testing log messages with log4j2

[seppestas]

When I try to create a (or fix an existing) unit test that checks for the existence of certain error messages with the LoggerContextRule, as described in the docs, I get the following error:

java: cannot access org.junit.rules.TestRule
  class file for org.junit.rules.TestRule not found

This happens on:

init = new LoggerContextRule("log4j2.xml");
LoggerContext ctx = init.getLoggerContext();

Dependencies (mvn):

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.19.0</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.19.0</version>
    <type>test-jar</type>
    <scope>test</scope>
</dependency>
<dependency>
    <groupId>junit</groupId>
    <artifactId>junit</artifactId>
    <version>4.8.2</version>
    <scope>test</scope>
</dependency>

Looking at the Junit docs, it looks like org.junit.rules.TestRule only became available in 4.9. However, after updating Junit to v4.13.2 I still get the same error.

I resorted to creating a custom ListAppender for testing things like custom Log4J appenders, but this only seems to work in that specific tests. Log events do not get written to the List Appender until the logger context is closed, which seems to require the logger to be re-opened. The core issue is likely that log4j2 seems to default to using an Async Logger, even for the most basic test configuration, I have yet to figure out how to make log4j use a synchronous logger instead.

My use-case is fairly straight forward, and I'm sure I'm not the only one that has the use-case: I want to check with Junit if a test that I expect to log, was in fact logged.

The recommended approach documented on the Log4j website seems broken due to Junit dependencies. Coming up with alternative approaches is painful due to many caveats like (often undocumented) lifetimes of objects and implicit asynchronous behaviour.

Could this use-case please be fixed / documented better?

[seppestas]

I should clarify, tests where I explicitly create new logger objects work, e.g:

@Test
public void testMarkerFilter() throws Exception {
  Logger logger = LogManager.getLogger("TestRingBufferAppenderDispatchedByMarker");

  final Marker MARK = MarkerManager.getMarker("MARK");

  logger.info("On yer mark!");
  logger.debug("Don't mind me");
  logger.info("Ready, set...");

  logger.info(MARK, "GO!");

  logger.info("Nothing interesting in here.");
  logger.debug("All is fine.");
  logger.error("Not even errors are interesting.");

  // Ensure all logs are flushed to the appropriate appenders
  LogManager.shutdown();

  List<LogEvent> events = listAppender.getEvents();
  assertEquals(3, events.size());
  assertEquals("On yer mark!", events.get(0).getMessage().getFormattedMessage());
  assertEquals("Ready, set...", events.get(1).getMessage().getFormattedMessage());
  assertEquals("GO!", events.get(2).getMessage().getFormattedMessage());
}

However, this does not work in a more typical scenario where it is the application managing the Logger object, not the test code. In this case, as soon as I call

LogManager.shutdown();

Subsequent logs no longer seem to work, and this is the only way I found to force synchronisation (dispatch events of an asynchronous logger to be flushed to the underlying appenders).

[vy]

This is not a direct response to your question, but I would like to share it anyway. I personally think one shouldn't create an entire LoggerContext et al. just to test the logging behaviour of a single class/method, but instead pass a mock Logger to the class/method that is supposed to be tested and verify the emitted LogEvents. As a matter of fact, I had already proposed a solution for this in May. In a nutshell, your test code will look as follows:

@Log4jEventRecorderEnabled
class LoggingDecodingExceptionHandlerTest {

    @Test
    void exceptions_should_get_logged(Log4jEventRecorder log4jEventRecorder) {

        // Execute the logic
        Logger logger = log4jEventRecorder.loggerContext().getLogger(Foo.class);
        new Foo(logger).runBusinessLogic(...);

        // Verify the logging
        List<LogEvent> events = log4jEventRecorder.events();
        // ...

    }

}

The code is already publicly available in dba68fd. If there is enough interest, I can make it an official part of log4j-core-test.

[seppestas]

The problem with passing the logger object to the code under test is that the code needs to support this dependency injection, on every level of the codebase. This is a bit tedious, and adapting big existing projects to this is a no-go for anyone that wants to keep their sanity.

IMHO it also goes against the whole "loggercontext" design approach of log4j. The whole idea is that it's easy to know where logs come from. Passing in a logger as a dependency would complicate this.

[vy]

The subject class whose logging behaviour to be unit tested can easily be extended with an alternative ctor accepting an extra logger argument. I have successfully practiced this for various projects, though I don't know your code base and YMMV. It just doesn't smell right to erect an entire application with a fully-blown LoggerContext just to test the logging behaviour of a single class/method.

Regarding the LoggerContext design approach of Log4j... IMO, it implies several shortcomings in a test context. LC depends on several ClassLoader- and thread-scope-specific state, and these can be dirtied/invalidated easily in tests. Not to mention parallel test runs become far from being practical, if not impossible.

Don't get me wrong, we don't need to agree. I just want to share my experience with the hope that it would help you too. Feel free to submit a PR if you think Log4j can do this better.