SLF4j with Log4j2 ERROR Unable to invoke factory method in class class ...RollingFileAppender for element RollingFile

Question

I have some WebDriver tests running in parallel in TestNG. And I want to be able to have logging log to a separate file for each test that's run in a directory structure like this:

target\logs\TestNGSuiteName(SuiteStartTime)
    Test1ClassName.TestMethod1 (TestStartTime).log
    Test1ClassName.TestMethod2 (TestStartTime).log

etc.

Using Log4j and SLF4j is it possible to create a separate log file for each individual TestNG tests?

I have attempted using a RollingFileAppender but it doesn't look like that is designed for having separate instances run for separate log files like I'm attempting to do here.

And I'm getting the errors

ERROR Unable to invoke factory method in class class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile.
Unable to create Appender of type RollingFile.

Log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
        <Routing name="Routing">
            <Routes pattern="$${ctx:ROUTINGKEY}">
                <Route>
                    <RollingFile name="Rolling-${ctx:ROUTINGKEY}"
                                 fileName="target/logs/${ctx:suiteTimestamp}/${ctx:testName} (${ctx:testStartTime}).log"
                                 filePattern="target/logs/${ctx:testname} ${ctx:testStartTime}_%i.log.gz">
                        <PatternLayout>
                            <pattern>%d{HH:mm:ss.SSS} [%t] %p %c{3} - %m%n</pattern>
                        </PatternLayout>
                        <Policies> <!-- 6 hour rollover-->
                            <TimeBasedTriggeringPolicy interval="6" modulate="true"/>
                            <SizeBasedTriggeringPolicy size="10 MB"/>
                        </Policies>
                    </RollingFile>
                </Route>
            </Routes>
        </Routing>
    </Appenders>
    <Loggers>
        <Logger name="james.log" level="debug" additivity="false">
            <AppenderRef ref="Routing"/>
        </Logger>
    </Loggers>
</Configuration>

LumberJack.java

package james.log;

import james.util.ConcurrentDateFormatAccess;
import org.apache.logging.log4j.ThreadContext;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.testng.ITestContext;
import org.testng.annotations.AfterMethod;
import org.testng.annotations.AfterSuite;
import org.testng.annotations.BeforeMethod;
import org.testng.annotations.Test;

import java.lang.reflect.Method;

/**
 * @author james.affleck
 */
public class LumberjackTest {
    private static final Logger logger = LoggerFactory.getLogger(LumberjackTest.class);
    private static ThreadLocal<String> methodLogName = new ThreadLocal<>();
    private static String suiteName = "";

    @BeforeMethod
    public void loggerDoTheThings(ITestContext context, Method method) {
        if(suiteName.isEmpty()) {
            String suite = context.getSuite().getName() + "(";
            String suiteTime = new ConcurrentDateFormatAccess().getCurrentDateSPrecision();
            suite += suiteTime + ")";
            suiteName = suite;
        }

        // Test filename = testClass.testMethodname
        String classname = this.getClass().getName();
        classname = classname.substring(classname.lastIndexOf(".") + 1); //get rid of package info we don't care about
        String testName = classname + "." + method.getName();

        // Using this to store logger instance for later
        String testStart = new ConcurrentDateFormatAccess().getCurrentDateMSPrecision();
        methodLogName.set(testName + testStart);

        ThreadContext.put("suiteTimestamp", suiteName);
        ThreadContext.put("testName", testName);
        ThreadContext.put("testStartTime", testStart);
    }

    @AfterMethod
    public void closeTheThings() {
        methodLogName.set(null);
    }
    @AfterSuite
    public void closeSuite() {
        suiteName = null;
    }

    @Test
    public void testLog1() {
        logThings();
    }

    @Test
    public void testLog2() {
        logThings();
    }

    public void logThings() {
        logger.info("info message");
        logger.debug("debug message");
        logger.warn("warn message");
    }
}

Answer 1

Log4j 2 seems to be pumped on steroids, if you get MDC logging for free already using the rolling file appender.

In any case, your log4j snippet looks strange. We see the closing appender element tag, but not its corresponding opening appender tag.

Your rolling file appender name seems to have a space between the dynamic test name and test start time.

fileName="target/logs/${ctx:suiteTimestamp}/${ctx:testName (${ctx:testStartTime}).log"

Suggestion: How about you divide conquer.

If such type of dynamic configuration is indeed supported. Why don't you try to configure first only the file name with a dynamic pattern?

You seem to be putting your log4j configuration on full steroids before you got the simplest possible configuration to work for your problem.

So put a feet on the break and focus on getting the: fileName="target/logs/dummyTest_dynamicComponent_${ctx:testName}.log"

To work for you.

In log4j 1.x version, you would have the log4j.debug system property to help you out figuring bugy configuration, and the output was very very useful.

Finally, on log4j 1.X version the feature you want to use would require you to program explicitly an MDC appender of your own. Your MDC appender would typically instantiate RollingFileAppenders to log into files and you would tap into the MDC context (keyxValue) pairs put by the user.

But what you're doing looks promising, just reduce the level of complexity of your configuration if it is not working for you.

Finally, I would be very surprised if you would see any log file geting created when you have the following error:

ERROR Unable to invoke factory method in class class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile. Unable to create Appender of type RollingFile.

Log4j is telling you: Hey, that appender you are defining. My factory that is trying to swallog this configuration cannot handle it and I will not instantiate a rolling file appender with this configuration.

So you have to fix that configuration.

---

Adding to answer.

Here you have a working Log4j 2 configuration for doing what you want:

First snippet if the log4j 2 configuration, where you will see that the root logger is given 3 different appenders to play around. You care mostly about appender 3, but the other two appenders are more of your typical starting point.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <!-- APPENDER 1: CONSOLE -->
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
        </Console>

        <!-- APPENDER 2: ROLLING FILE -->
        <RollingFile name="AppenderTwo" fileName="target/logs/test.log" filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz">
            <PatternLayout>
                <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="10 MB" />
            </Policies>
        </RollingFile>

        <!-- APPENDER 3: ROUTING APPENDER -->
        <Routing name="AppenderThree">
            <Routes pattern="${ctx:stackOverFlow}">
                <!-- Route Nr.1 -->
                <Route>
                    <!-- Rolling file appender for route Nr.1 -->
                    <RollingFile name="NestedAppender-${ctx:stackOverFlow}" fileName="target/logs/test_threadContext_${ctx:stackOverFlow}.log"
                        filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz">
                        <PatternLayout>
                            <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
                        </PatternLayout>
                        <Policies>
                            <TimeBasedTriggeringPolicy />
                            <SizeBasedTriggeringPolicy size="10 MB" />
                        </Policies>
                    </RollingFile>
                </Route>

                <!-- Route Nr.2 fallback -->
                <!-- By having this set to ${ctx:filename} it will match when filename is not set in the context -->
                <Route ref="Console" key="${ctx:stackOverFlow}" />
            </Routes>
        </Routing>


    </Appenders>
    <Loggers>
        <Root level="all">
            <AppenderRef ref="Console" />
            <AppenderRef ref="AppenderTwo" />
            <AppenderRef ref="AppenderThree" />
        </Root>

    </Loggers>
</Configuration>

This last appender is configured based on the following thread: https://issues.apache.org/jira/browse/LOG4J2-129

The second snippet is a dummy junit test that you get out of eclipse when you create a new maven project out of a basic archetype. You will see in the test snippet that the stack over flow context context is being set in to the thread context, like you do in your snippets.

package stackoverflow.test.tutorial;

import org.apache.logging.log4j.ThreadContext;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import junit.framework.Test;
import junit.framework.TestCase;
import junit.framework.TestSuite;

/**
 * Unit test for simple App.
 */
public class AppTest extends TestCase {
    private static final Logger LOGGER = LoggerFactory.getLogger(TestCase.class);

    /**
     * Create the test case
     *
     * @param testName
     *            name of the test case
     */
    public AppTest(String testName) {
        super(testName);
    }

    /**
     * @return the suite of tests being tested
     */
    public static Test suite() {
        return new TestSuite(AppTest.class);
    }

    /**
     * Rigourous Test :-)
     */
    public void testApp() {
        ThreadContext.put("stackOverFlow", "dummyContextValue");
        LOGGER.info("LALAL LLA");
        assertTrue(true);
    }
}

The last snippet are the maven dependencies:

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
  xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
  <modelVersion>4.0.0</modelVersion>

  <groupId>stackoverflow.test</groupId>
  <artifactId>tutorial</artifactId>
  <version>0.0.1-SNAPSHOT</version>
  <packaging>jar</packaging>

  <name>tutorial</name>
  <url>http://maven.apache.org</url>

  <properties>
    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
  </properties>

  <dependencies>
   <dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.12</version>    
  </dependency>  
    <dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-api</artifactId>
    <version>2.5</version>
    <scope>runtime</scope>
  </dependency>
  <dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.5</version>
    <scope>runtime</scope>
  </dependency>
  <dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-slf4j-impl</artifactId>
    <version>2.5</version>
</dependency>

    <dependency>
      <groupId>junit</groupId>
      <artifactId>junit</artifactId>
      <version>3.8.1</version>
      <scope>test</scope>
    </dependency>
  </dependencies>
</project>

I find funy that log4j brings in this new Routing Appender. If you could imagine how many people have had to implement their own rolling file appenders with MDC context support to do this type of stuff. It is very useful in web apps.

Cheers.