Log4j2: Empty log file in case of parallel tests

Question

I have in my test automation project problem with logging. I'm using log4j2 logger with FileAppender. The way I'm using it is:

Logger logger = (Logger) LogManager.getLogger(loggerName);
Appender appender = FileAppender.newBuilder()
            .withAppend(false)
            .withBufferedIo(true)
            .withFileName(DIR_NAME + File.separator + loggerName + ".log")
            .withIgnoreExceptions(false)
            .withImmediateFlush(true)
            .withLocking(false)
            .withLayout(PatternLayout.newBuilder().withPattern("%d{HH:mm:ss.SSS}  [%-5level] %msg%n").withCharset(Charset.forName("UTF-8")).build())
            .withName(loggerName)
            .build();

    appender.start();
    logger.addAppender(appender);

It works when I'm running single test. All data are visible in console, the file is created and test log is written in the file. Problem occurs in case of tests are running in parallel - in different threads.

In this case, two different loggers and file appenders are created. Log files from both file appenders are created too and logs from both tests are visible in console. Everything seems to be fine, but every time one of these log files is empty. The empty log belongs to test which started later.

I suspect problem with caching. The first file appender holds all cache for writing so the second one is not able to write. Am I right? What is the solution for this?

Thank you.

Answer 1

You should be able to achieve what you want without using programmatic configuration. There are many reasons not to configure log4j2 programmatically, but the best one, in my opinion, is that in doing so you would make your code dependent on aspects of log4j2 that are not part of the public API. This means that if the implementation of log4j2 changes your code has to change as well. This creates more work for you in the long run.

So, with that in mind I will provide a demo of how to set up log4j2 using an XML config file such that it will generate separate logs for each test. I am assuming, since it was not specified in your question, that your goal is to create a log for each method with a Test annotation and that each of these methods is executed in parallel.

First, here is my TestNG class:

package testpkg;

import java.lang.reflect.Method;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.ThreadContext;
import org.testng.annotations.BeforeMethod;
import org.testng.annotations.Test;

public class NewTest {
    private static final Logger log = LogManager.getLogger();

    @BeforeMethod
    public void setThreadName(Method method){
        ThreadContext.put("threadName", method.getName());
    }

    @Test
    public void test1() {
        log.info("This is the first test!");
        log.warn("Something may be wrong, better take a look.");
    }

    @Test
    public void test2() {
        log.info("Here's the second test!");
        log.error("There's a problem, better fix it");
    }
}

As you can see here I have two Test methods and a BeforeMethod called setThreadName. The setThreadName method is, obviously, executed before each of the Test methods. It places a key named threadName into the log4j2 ThreadContext using the name of the method that is about to be run. This will be used as part of the log file name in the log4j2 config file.

Here is the log4j2.xml file:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Routing name="MyRoutingAppender">
            <Routes pattern="$${ctx:threadName}">
                <Route>
                    <File
                        fileName="logs/${ctx:threadName}.log"
                        name="appender-${ctx:threadName}"
                        append="false">
                        <PatternLayout>
                            <Pattern>[%date{ISO8601}][%-5level][%t] %m%n</Pattern>
                        </PatternLayout>
                    </File>
                </Route>
            </Routes>
        </Routing>
        <Console name="STDOUT" target="SYSTEM_OUT">
            <PatternLayout pattern="[%date{ISO8601}][%-5level][%t] %m%n" />
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="testpkg" level="TRACE" additivity="false">
            <AppenderRef ref="STDOUT" />
            <AppenderRef ref="MyRoutingAppender" />
        </Logger>
        <Root level="WARN">
            <AppenderRef ref="STDOUT" />
        </Root>
    </Loggers>
</Configuration>

As you can see I've set up the config file to use a RoutingAppender to dynamically generate appenders at runtime based on the ThreadContext key threadName and that threadName is also used in the fileName attribute of the FileAppender.

Here is my testNG config file:

<!DOCTYPE suite SYSTEM "http://testng.org/testng-1.0.dtd" >

<suite name="My suite" parallel="methods" thread-count="5" verbose="1">
  <test name="testpkg" >
    <classes>
       <class name="testpkg.NewTest" />
    </classes>
  </test>
</suite>

As you can see here I've set it up so that each Test method within my class is run in parallel.

When executed this results in the following console output:

[RemoteTestNG] detected TestNG version 6.14.3
[2018-05-04T21:54:54,703][INFO ][TestNG-test=testpkg-2] Here's the second test!
[2018-05-04T21:54:54,703][INFO ][TestNG-test=testpkg-1] This is the first test!
[2018-05-04T21:54:54,709][WARN ][TestNG-test=testpkg-1] Something may be wrong, better take a look.
[2018-05-04T21:54:54,709][ERROR][TestNG-test=testpkg-2] There's a problem, better fix it

===============================================
My suite
Total tests run: 2, Failures: 0, Skips: 0
===============================================

You can clearly see that the output of the two methods is interleaved, so we know that the methods are indeed running in parallel.

The execution of the test class also creates two log files as expected. They are named test1.log and test2.log

Here are their contents:

test1.log:

[2018-05-04T21:54:54,703][INFO ][TestNG-test=testpkg-1] This is the first test!
[2018-05-04T21:54:54,709][WARN ][TestNG-test=testpkg-1] Something may be wrong, better take a look.

test2.log:

[2018-05-04T21:54:54,703][INFO ][TestNG-test=testpkg-2] Here's the second test!
[2018-05-04T21:54:54,709][ERROR][TestNG-test=testpkg-2] There's a problem, better fix it

So we see here that as expected the logs from the first method went to test1.log and the logs from the second method went to test2.log

Enjoy!