How To Use Log4j With Example

Log is a process of recording information that happen and saved when an application is running in a centralized place. With logs, we will able to review information about past application activities, such as application health, stack trace when an error occurred or exception happen, and so on.

Apache Log4j

Log4j is a library provided by Apache that supports logging in Java.

The main components of Log4j::

logger: this is what we use in the application to issue messages.
appender: component in charge for displaying log messages
category: the source of the log message, i.e. package or realm.

Besides those three components, there is a terminology called level.

level: used for identifying the severity of an event

Logger

Logger is an object that is responsible for issuing log messages. This is the main object that we use in our code for logging.

Appender

There are many ways to log: it can be saved to a file, console (or command prompt), a database, or elsewhere for review. Appender is an object which responsible to display log messages. Two commonly used appenders:

ConsoleAppender: to display log messages to the console or command prompt
RollingFileAppender: to save the log in a file. We can configure this file for file name, maximum size, and number of backups to be made.

In practical, only showing logs to the console is insufficient because there are some limitations:

Only show results in console. Therefore, every time the console is closed, all log information shown on the console will be lost.
The log contents displayed on the console are difficult to review later.

In addition to above two appenders, there is also an appender for save to database, send email, access system log operations, and many more.

Level

By default, log4j provides several levels of logging, sorted from the least important:

Level	Description
TRACE	designates finer-grained informational events than the DEBUG, typically capturing the flow through the application
DEBUG	designates fine-grained informational events that are most useful to debug an application
INFO	designates informational messages that highlight the progress of the application at coarse-grained level
WARN	designates potentially harmful situations, or an event that might possible lead to an error
ERROR	designates error events that might still allow the application to continue running
FATAL	designates very severe error events that will prevent the application from continuing

If these six levels are not enough, we still able to define our own customized level.

We can choose one of the level as a logging threshold. Log messages that have the same level or below the threshold will be displayed. For example, if the threshold is INFO, then log messages with level INFO, WARN, ERROR, FATAL will displayed. If the threshold is WARN, then the TRACE level, DEBUG, and INFO will not appear.

Besides above six levels, there are two more levels that actually working like flag:

ALL: the lowest possible rank, all events should be logged

OFF: the highest possible rank, no events will be logged

With ALL and OFF the priority of the log levels from low to high is as follows:

(least specific, more of data) ALL < DEBUG < INFO < WARN < ERROR < FATAL < OFF (most specific, less data)

Using log4j

To use Log4j, we need to follow these steps:

Add Log4j dependency
Set Log4j configuration.
Set the log statements in the application

We add log4j dependency in maven pom.xml:

<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.17</version>
</dependency>

We will set log4j configuration later on this tutorial, we proceed first to add log statements in the application.

For example, we will create a class named WorldDominationDao. In this class, we will declare the object logger.

WorldDominationDao.java

package com.dariawan.log4j.dao;

import java.text.MessageFormat;
import org.apache.log4j.Logger;

public class WorldDominationDao {

    private final Logger logger = Logger.getLogger(this.getClass());

    public void divide(int number1, int number2) {
        logger.debug("Run divide method");

        String message;
        try {
            int number = number1 / number2;
            if (logger.isDebugEnabled()) {
                message = MessageFormat.format("Info: {0} / {1} = {2}", number1, number2, number);
                logger.debug(message);
            }
        } catch (ArithmeticException e) {
            message = MessageFormat.format("Error: Cannot divide two number {0} / {1}", number1, number2);
            logger.error(message, e);
        }
    }

    public void conquer(int days) {
        logger.debug("Run conquer method");

        if (days < 0) {
            throw new IllegalArgumentException("Days must be greater than zero");
        } else {
            if (logger.isInfoEnabled()) {
                logger.debug(MessageFormat.format("Take over the world in {0} days", days));
            }
        }
    }

    public void destroy() {
        throw new IllegalStateException("Cannot run destroy method");
    }
}

getLogger(Class clazz)is shorthand for getLogger(clazz.getName()), to retrieve a logger named according to the parameter. If the named logger already exists, then the existing instance will be returned. Otherwise, a new instance is created. So in our case, the logger object is named after the class name:

private final Logger logger = Logger.getLogger(this.getClass());

We can use this logger object, as example in method divide as follows:

logger.debug("Run divide method");

Often, we need to display the contents of variables for debugging. Like what we do in the divide method.

int number = number1 / number2;
message = MessageFormat.format("Info: {0} / {1} = {2}", number1, number2, number);
logger.debug(message);

Detects Active Level

boolean isDebugEnabled(): check whether this category is enabled for the DEBUG Level.

boolean isInfoEnabled(): check whether this category is enabled for the INFO Level.

boolean isTraceEnabled(): check whether this category is enabled for the TRACE Level.

boolean isEnabledFor(Priority level): check whether this category is enabled for a given Level passed as parameter.

As example, from method divide above:

message = MessageFormat.format("Info: {0} / {1} = {2}", number1, number2, number);
logger.debug(message);

In this case, you incur the cost constructing the message, concatenation in this case, regardless of whether the message is logged or not. The isDebugEnabled()check is intended to lessen the computational cost of disabled log debug statements:

if (logger.isDebugEnabled()) {
    message = MessageFormat.format("Info: {0} / {1} = {2}", number1, number2, number);
    logger.debug(message);
}

This way you will not incur the cost of parameter construction if debugging is disabled for logger. On the other hand, if the loggeris debug enabled, you will incur the cost of evaluating whether the category is debug enabled twice. Once in isDebugEnabled and once in the debug. This is an insignificant overhead since evaluating a category takes about 1%% of the time it takes to actually log.

Logging for Exception

Next, is on how to logging for exceptions. If an exception occurs, we want to retrieve all available information for troubleshooting. As example we can found in conquer method to raise exception if days is less than zero.

public void conquer(int days) {
    logger.debug("Run conquer method");

    if (days < 0) {
        throw new IllegalArgumentException("Days must be greater than zero");
    } else {
        if (logger.isInfoEnabled()) {
            logger.debug(MessageFormat.format("Take over the world in {0} days", days));
        }
    }
}

Let's catch this exception in the class WorldDominationService::conquerTheWorld(int days)

public void conquerTheWorld(int days) {
    logger.warn("Run conquerTheWorld");
    try {
        worldDominationDao.conquer(days);
    } catch (IllegalArgumentException e) {
        logger.error(e.getMessage(), e);
    }
}

We use try-catch block to catch IllegalArgumentException, and then log error message with the Exception object itself. In this way, we can capture all information contained in the exception. Here the full WorldDominationService

WorldDominationService.java

package com.dariawan.log4j.service;

import com.dariawan.log4j.dao.WorldDominationDao;
import org.apache.log4j.Logger;

public class WorldDominationService {

    private final Logger logger = Logger.getLogger(this.getClass());

    private WorldDominationDao worldDominationDao;

    public void setWorldDominationDao(WorldDominationDao worldDominationDao) {
        this.worldDominationDao = worldDominationDao;
    }

    public void divideTheWorld(int number1, int number2) {
        logger.warn("Run divideTheWorld");
        worldDominationDao.divide(number1, number2);
    }

    public void conquerTheWorld(int days) {
        logger.warn("Run conquerTheWorld");
        try {
            worldDominationDao.conquer(days);
        } catch (IllegalArgumentException e) {
            logger.error(e.getMessage(), e);
        }
    }
    
    public void destroyTheWorld() {
        logger.warn("Run destroyTheWorld");
        try {
            worldDominationDao.destroy();
        } catch (IllegalStateException e) {
            logger.fatal(e.getMessage(), e);
        }
    }
}

For this example, we try to create similar structure like a Spring application (also for the sake of category). Next is WorldDominationController

WorldDominationController.java

package com.dariawan.log4j.controller;

import com.dariawan.log4j.dao.WorldDominationDao;
import com.dariawan.log4j.service.WorldDominationService;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;

public class WorldDominationController {

    private final Logger logger = Logger.getLogger(this.getClass());

    private static WorldDominationController worldDominationController = null;

    public static WorldDominationController getInstance() {
        if (worldDominationController == null) {
            worldDominationController = new WorldDominationController();
        }
        return worldDominationController;
    }

    public void takeOverTheWorld() {
        logger.log(Level.TRACE, "Create dao");
        WorldDominationDao dao = new WorldDominationDao();

        logger.log(Level.TRACE, "Create service");
        WorldDominationService service = new WorldDominationService();

        logger.log(Level.TRACE, "Set Dao to service");
        service.setWorldDominationDao(dao);

        // Run method divide
        logger.log(Level.TRACE, "Divide the world");
        service.divideTheWorld(5, 3);
        service.divideTheWorld(6, 0);

        // Run method conquer 
        logger.log(Level.TRACE, "Conquer the world");
        service.conquerTheWorld(-1);
        service.conquerTheWorld(10);

        // Run method destroy 
        logger.log(Level.TRACE, "Destroy the world");
        service.destroyTheWorld();
    }
}

Finally, let's create the main class, WorldDominationApp

WorldDominationApp.java

package com.dariawan.log4j;

import com.dariawan.log4j.controller.WorldDominationController;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;

public class WorldDominationApp {
 
    private static final Logger LOGGER = Logger.getLogger(WorldDominationApp.class);
    
    public static void main(String[] args) {
        // start...
        LOGGER.trace("This is a TRACE message");
        LOGGER.debug("This is a DEBUG message");
        LOGGER.info("This is an INFO message");
        LOGGER.warn("This is a WARN message");
        LOGGER.error("This is an ERROR message");
        LOGGER.fatal("This is a FATAL message");
        
        LOGGER.log(Level.DEBUG, "Method WorldDominationApp.main() start");
        
        WorldDominationController controller= WorldDominationController.getInstance();
        controller.takeOverTheWorld();
        
        LOGGER.log(Level.DEBUG, "Method WorldDominationApp.main() completed");
    }
}

Log4j Configuration

Put log4j.properties in /src/main/resources (using maven).

log4j.properties

# Root logger option
log4j.rootLogger=ERROR, stdout

# Redirect log messages to console
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5p %l - %m%n

log4j.logger.com.dariawan.log4j=WARN, stdout
log4j.additivity.com.dariawan.log4j=false

log4j.logger.com.dariawan.log4j.dao=DEBUG, stdout
log4j.additivity.com.dariawan.log4j.dao=false

Above configuration will display a log message to console:

2019-11-27 23:53:40.078 [main] WARN  com.dariawan.log4j.WorldDominationApp.main(WorldDominationApp.java:54) - This is a WARN message
2019-11-27 23:53:40.080 [main] ERROR com.dariawan.log4j.WorldDominationApp.main(WorldDominationApp.java:55) - This is an ERROR message
2019-11-27 23:53:40.080 [main] FATAL com.dariawan.log4j.WorldDominationApp.main(WorldDominationApp.java:56) - This is a FATAL message
2019-11-27 23:53:40.083 [main] WARN  com.dariawan.log4j.service.WorldDominationService.divideTheWorld(WorldDominationService.java:50) - Run divideTheWorld
2019-11-27 23:53:40.083 [main] DEBUG com.dariawan.log4j.dao.WorldDominationDao.divide(WorldDominationDao.java:44) - Run divide method
2019-11-27 23:53:40.084 [main] DEBUG com.dariawan.log4j.dao.WorldDominationDao.divide(WorldDominationDao.java:51) - Info: 5 / 3 = 1
2019-11-27 23:53:40.086 [main] WARN  com.dariawan.log4j.service.WorldDominationService.divideTheWorld(WorldDominationService.java:50) - Run divideTheWorld
2019-11-27 23:53:40.086 [main] DEBUG com.dariawan.log4j.dao.WorldDominationDao.divide(WorldDominationDao.java:44) - Run divide method
2019-11-27 23:53:40.087 [main] ERROR com.dariawan.log4j.dao.WorldDominationDao.divide(WorldDominationDao.java:55) - Error: Cannot divide two number 6 / 0
java.lang.ArithmeticException: / by zero
	at com.dariawan.log4j.dao.WorldDominationDao.divide(WorldDominationDao.java:48)
	at com.dariawan.log4j.service.WorldDominationService.divideTheWorld(WorldDominationService.java:51)
	at com.dariawan.log4j.controller.WorldDominationController.takeOverTheWorld(WorldDominationController.java:67)
	at com.dariawan.log4j.WorldDominationApp.main(WorldDominationApp.java:61)
2019-11-27 23:53:40.090 [main] WARN  com.dariawan.log4j.service.WorldDominationService.conquerTheWorld(WorldDominationService.java:55) - Run conquerTheWorld
2019-11-27 23:53:40.090 [main] DEBUG com.dariawan.log4j.dao.WorldDominationDao.conquer(WorldDominationDao.java:60) - Run conquer method
2019-11-27 23:53:40.090 [main] ERROR com.dariawan.log4j.service.WorldDominationService.conquerTheWorld(WorldDominationService.java:59) - Days must be greater than zero
java.lang.IllegalArgumentException: Days must be greater than zero
	at com.dariawan.log4j.dao.WorldDominationDao.conquer(WorldDominationDao.java:63)
	at com.dariawan.log4j.service.WorldDominationService.conquerTheWorld(WorldDominationService.java:57)
	at com.dariawan.log4j.controller.WorldDominationController.takeOverTheWorld(WorldDominationController.java:71)
	at com.dariawan.log4j.WorldDominationApp.main(WorldDominationApp.java:61)
2019-11-27 23:53:40.090 [main] WARN  com.dariawan.log4j.service.WorldDominationService.conquerTheWorld(WorldDominationService.java:55) - Run conquerTheWorld
2019-11-27 23:53:40.090 [main] DEBUG com.dariawan.log4j.dao.WorldDominationDao.conquer(WorldDominationDao.java:60) - Run conquer method
2019-11-27 23:53:40.091 [main] DEBUG com.dariawan.log4j.dao.WorldDominationDao.conquer(WorldDominationDao.java:66) - Take over the world in 10 days
2019-11-27 23:53:40.091 [main] WARN  com.dariawan.log4j.service.WorldDominationService.destroyTheWorld(WorldDominationService.java:64) - Run destroyTheWorld
2019-11-27 23:53:40.093 [main] FATAL com.dariawan.log4j.service.WorldDominationService.destroyTheWorld(WorldDominationService.java:68) - Cannot run destroy method
java.lang.IllegalStateException: Cannot run destroy method
	at com.dariawan.log4j.dao.WorldDominationDao.destroy(WorldDominationDao.java:72)
	at com.dariawan.log4j.service.WorldDominationService.destroyTheWorld(WorldDominationService.java:66)
	at com.dariawan.log4j.controller.WorldDominationController.takeOverTheWorld(WorldDominationController.java:76)
	at com.dariawan.log4j.WorldDominationApp.main(WorldDominationApp.java:61)

Output to Log Files

After successfully displaying the log message to the console, now we will save the log message to a file. The DailyRollingFileAppender can automatically create new file (rolled over) at a user chosen frequency . Following is the configuration for DailyRollingFileAppender. This new appender's name is file.

log4j.properties

# Root logger option
log4j.rootLogger=ERROR, stdout, file

# ConsoleAppender
log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target=System.out
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5p %l - %m%n

log4j.logger.com.dariawan.log4j=WARN, stdout
log4j.additivity.com.dariawan.log4j=false

log4j.logger.com.dariawan.log4j.dao=DEBUG, stdout, file
log4j.additivity.com.dariawan.log4j.dao=false

# DailyRollingFileAppender 
log4j.appender.file=org.apache.log4j.DailyRollingFileAppender 
log4j.appender.file.File=logs/app.log 
log4j.appender.file.DatePattern='.'yyyy-MM-dd
log4j.appender.file.layout=org.apache.log4j.PatternLayout 
log4j.appender.file.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5p %l - %m%n

Each log file is rolled out every day and the file without date in its name is the current log file. If today is 2019-11-27 and at midnight, Log4j will back up the current app.log file into the app.log.2019-11-27. Then the current app.log is the current logging file for new day i.e. 2019-11-28, until it roll on next day.

Note: DailyRollingFileAppender has been observed to exhibit synchronization issues and data loss. The log4j extras companion includes alternatives which should be considered for new deployments and which are discussed in the documentation for org.apache.log4j.rolling.RollingFileAppender.

Configure Output Message

We use patterns to configure display of log messages. Here the break-down of conversion pattern in our example:

%d : date/time when the log captured
%t : thread name
%p : log level, like DEBUG or ERROR
%l : location of the caller which generated the logging event
%m%n = The message to log and line break

Filtering

Our log4j.properties also contains example on how to filter based on level:

log4j.rootLogger=ERROR, stdout, file

Or based on category:

log4j.logger.com.dariawan.log4j=WARN, stdout
log4j.logger.com.dariawan.log4j.dao=DEBUG, stdout, file

Conclusion

This is end the explanation of the concept and usage of classic Log4j. A carefully crafted log message make application tuning, monitoring, and troubleshooting, even development easier.

On August 5, 2015 is announced that Log4j 1.x had reached end of life. Users of Log4j 1 are recommended to upgrade to Apache Log4j 2

← Java 13 - Text Blocks (JEP 355)

Published 27 November 2019

Desson AriawanProgrammer

Java 14 - Pattern Matching for instanceof (JEP 305)

Desson Ariawan