Logging Test Automation Information with Log4j

We run our automated tests either on our local machines or in CI systems. In some cases, we cannot see what the tests are doing. When it is an API test, unless it provides some output to the console, we are unaware of what is going on until the test finishes. If it is a UI test, unless we see what happens in the browser, we again have no clue about what is going on. This is why, in some cases, we need to output information to the console. This information will give us an overview of the test state or data used by the test. One option to write test output to the console is to use the Apache Log4j library.

The simplest use of this library in our test automation project is to log information we tell it to. This is very similar to performing a System.out, but it is a bit more configurable. And the output can be configured to follow certain patterns, so that we can easily search for particular types of output.

What sort of information would we want to output though? Well, if we are talking about long UI tests, we could send a message to the console when a certain step begins, or when it finished successfully. If we are using some random generated data, like dates or names, we could print these to the console. Such information would help with easily trying to manually reproduce a scenario that failed.

The more information we output, the better we understand what our tests are doing. However, too much output will make it really hard to read it, and we will tend to skip certain information, or simply not see it. Therefore it’s important to only log information that is relevant to the test run and possible test failure.

Importing Log4j into your Maven project

If you have a Maven project, you should go to the Maven repository site, and search for ‘log4j-core’. Then, pick the latest release version. For now, here is the dependency you should add to your pom.xml file for the currently available version:

<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-core</artifactId>
    <version>2.14.1</version>
</dependency>

Don’t forget to perform a ‘clean install’ operation on your project before proceeding to use this library in your tests.

Configuration file

Before using the library, you need to create a configuration file. The only requirement regarding where it should be placed is for it to be in the classpath. But because this is a configuration used in tests, I recommend creating it under src\test\resources. The name of the file should be ‘log4j2.xml’. A basic configuration file can look like this:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss} %-5level %class.%method{36} - %msg%n"/>
        </Console>
    </Appenders>
<Loggers>
    <Root level="all">
        <AppenderRef ref="Console"/>
    </Root>
</Loggers>
</Configuration>

In the Appenders section, the pattern for the system output is configured. This means that every time something will be logged, as per the above example, the following information will be printed to the console: a timestamp consisting of hour, minute and seconds; the level (which I will discuss in the next paragraph); the class and method name from where the logging is done; the actual message, as a String, and then a newline. An example of what the formatted output looks like:

22:05:05 INFO com.imalittletester.log4j.Log4jTest.firstTest - This is a message of type: info

In the ‘Root’ tag, we set the logging level. In the above example, the logging level is ‘all’.

Logging levels

As I have mentioned earlier, too much logged information could make it more difficult to read it. But it would be great to log the most crucial information. Or, at least, if we log everything, to have a way to, for a certain test run, ignore the irrelevant information. This is what levels are useful for.

By default, Log4j supports a few standard levels. They are, in decreasing order of severity: FATAL, ERROR, WARN, INFO, DEBUG, TRACE. When we want to log information, the FATAL level should be used for the most crucial one. If we think of how developers would use this level: they would signal that a severe error occurred while running the application. Next, when they would use ERROR: they would still signal an ERROR, but with less impact than a FATAL error. Of course, the least severe level would be TRACE.

Because, as we will see in the ‘Setting the logging level’ paragraph, we can configure the levels, consider that we can restrict a test run to only show the most relevant output, or to show everything. Therefore do differentiate between these levels when you are logging the test output.

Logging in tests

First, we need to initialize the logger. We can do this either directly in a test class, or in a class that each test extends (a base class). Let’s assume that all tests extend a base class. In this case, we will initialize a protected variable:

protected static final Logger LOGGER = LogManager.getLogger();

The required imports for our logging are:

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

Now, each test class can log test run information by using the “LOGGER” variable. Logging is done by calling a method on the LOGGER variable corresponding to the level for which we are logging. Based on each level, the console output will be colored differently. Although in tests we might only need 2-3 levels, let’s look at how to log for all standard ones. Here we are passing a simple String as parameter. That parameter represents the message we want to display at the console:

trace:

LOGGER.trace("This is a message of type: trace");

debug:

LOGGER.debug("This is a message of type: debug");

info:

LOGGER.info("This is a message of type: info");

warn:

LOGGER.warn("This is a message of type: warn");

error:

LOGGER.error("This is a message of type: error");

fatal:

LOGGER.fatal("This is a message of type: fatal");

The output of all the above commands, when running the tests from IntelliJ, looks as follows:

As you can see in the screenshot, INFO looks exactly as any regular System.out. The rest of the resulting logging details are colored based on ‘severity’. The ‘fatal’ logging is highlighted in red. It suggests some information that is of utmost importance. Similarly, the ‘error’ level is highlighted in orange. It is the second most important type of logging information.

You can think about logging with different levels as: the nice to have details should be on a lower severity level, like INFO. The most important information, that needs to easily pop into view when running the tests, should be on the FATAL or ERROR levels.

Note: in certain CI systems, the colors will not appear in the console output. When running tests from an IDE like IntelliJ, they do. In this case, in the CI, if you are looking for a certain output, you can search based on the level name.

Setting the logging level

In the case of these examples, all the above commands ran successfully (all the logging was outputed). That is because in the log4j configuration file the level, in the Root tag, is set to ‘all’. This setting helps restrict what type of information you want to see when running a test. Let’s say that at a certain run, you only want to see the ‘must have’ information, not the ‘nice to have one’. For such a situation, you need to set the level to a different, more restrictive value. For example, if you want to see only ‘error’ and ‘fatal’ information, the level in the ‘Root’ tag should be set to ‘error’.