Lesson 17: Logging With log4j Version 2

Most, if not all, applications require a durable audit trail of their significant activity. We call this logging of events, and among the reasons for logging events might be:

• Legal requirements
• Notifying users of the start and end of a run
• Significant problems with input data
• Java Exceptions

Your humble servant has seen applications that log every record they process to a file meant to be read by humans. Thus important messages become needles buried in a haystack. Fortunately, log4j provides means to write to nearly any kind of output sink, including searchable databases which are much more suitable for logging large numbers of events.

Java provides a number of software component packages for logging. Probably the most popular is log4j from our old friend, the Apache Software Foundation.

However, in 2015, Apache released version 2 of log4j. Your Java shop may still be using version 1, which has significant differences from version 2. Even so, given that version 2 has been around for seven years as of this writing, we’ll discuss that. If you’re working where version 1 is still in use, your colleagues will know what to do.

Adding log4j2 to a Project

Now that you’ve got the necessary software, let’s add log4j2 to a project. Click here to download Lesson-17-Example-01 and import it to your workspace.

The first thing you might notice is compile errors. This project needs the JAR files we downloaded, and doesn’t know where to find them. They happen to be in our user library.

• Right-click on project Lesson-17-Example-01 in the Package Explorer. Select Build Path…/Configure Build Path… from the popup menu.
• In the Java Build Path dialog, select Classpath in the center window and click the Add Library… button.
• In the Add Library dialog, select User Library and click Next.
• Check the box next to log4j2, the library we created in Lesson 16, and click Finish.
  
  
  
• Click Apply and Close.

And now project Lesson-17-Example-01 should compile cleanly. Open Main.java and run it. The console output should look like this:

14:53:50.693 [main] ERROR org.practicaljava.lesson17.exercise01.FirstLogClass - This is an error message from FirstLogClass
14:53:50.695 [main] FATAL org.practicaljava.lesson17.exercise01.FirstLogClass - This is a fatal message from FirstLogClass
14:53:50.696 [main] ERROR org.practicaljava.lesson17.exercise01.SecondLogClass - This is an error message from SecondLogClass
14:53:50.696 [main] FATAL org.practicaljava.lesson17.exercise01.SecondLogClass - This is a fatal message from SecondLogClass

Congratulations! You’ve just run your first logging job. So what’s just happened? Your Main class instantiated and ran a method in each of two other classes: FirstLogClass and SecondLogClass. They’re pretty much identical:

package org.practicaljava.lesson17.exercise01;

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

public class FirstLogClass {
    private static Logger logger = LogManager.getLogger();

    public void performSomeTask(){
        logger.debug("This is a debug message from FirstLogClass");
        logger.info("This is an info message from FirstLogClass");
        logger.warn("This is a warn message from FirstLogClass");
        logger.error("This is an error message from FirstLogClass");
        logger.fatal("This is a fatal message from FirstLogClass");
    }

}

Notice that the class has a static variable named logger, which is initialized to an instance of an implementation of the Logger interface obtained from LogManager. This Logger actually has a name in the log4j2 system, and the getLogger() method has many overloads that allow you to specify the the source of the name: a String, a Class, and more. In this case, it uses the default: the name of the class that called getLogger().

Finally, you made several calls to the Logger to produce messages (known as events) in the log–in this case, the console.

And that’s all you need to know about logging.

Well, then again, not quite….

Why Does The Log Look That Way?

So the first thing you may have noticed is that most of the calls to logger methods didn’t produce anything. And what about all that other text that isn’t part of the strings you passed? That’s because we haven’t configured the logger, and when the logger isn’t configured, it has two defaults:

• A logging level threshold of ERROR
• A pattern of: “%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} – %msg%n”, which means:
  • Date/time stamp in format HH:mm:ss.SSS (same meaning as in SimpleDateFormat): %d{HH:mm:ss.SSS}
  • Thread name enclosed in literal text brackets: [%t]
  • The level, left justified with a width of 5 characters (padded or truncated if necessary): %-5level
  • Logger name limited to the last 36 levels of qualification: %logger{36}
  • Literal text–a hyphen: –
  • The message text: %msg
  • A newline: %n

Logging Levels

We’ve spoken of logging levels. Levels define the severity of a log event, and have a hierarchy. From most to least severe, they are:

• OFF: Let no messages through
• FATAL: To indicate a condition that requires terminating the application.
• ERROR: A serious error but less than fatal.
• WARN: A warning message, such as to indicate a problem with input data that doesn’t impede normal execution.
• INFO: An informational message, such as for the start or end of a run.
• DEBUG: For debugging, and intended to be suppressed in production.
• TRACE: Like DEBUG, but lower in priority
• ALL: No restrictions

OFF, ALL, and TRACE are new to log4j version 2.

As we’ve mentioned, the default level is ERROR. And the calls to logger.warn(), logger.info(), etc. above reflect the level of the corresponding log event; if it doesn’t reach the log’s configured level, the event is filtered out.

log4j2 supports custom logging levels too, but in my experience these have been more than sufficient.

Logging an Exception

Since one of the most important things to log is an Exception (or to be more precise, a Throwable), each of the calls above has an overload specifically for Throwables, and it looks like this:

        Exception e = new Exception("Oops!");
        logger.error("Oh, no!", e);

Adding the Exception (which is a Throwable) to the call yields the message followed by a stack trace:

15:57:32.840 [main] ERROR org.practicaljava.lesson17.exercise01.FirstLogClass - Oh, no!
java.lang.Exception: Oops!
	at org.practicaljava.lesson17.exercise01.FirstLogClass.performSomeTask(FirstLogClass.java:17) ~[bin/:?]
	at org.practicaljava.lesson17.exercise01.Main.main(Main.java:6) ~[bin/:?]

Configuring the Loggers

Usually, you’ll want more control over what your loggers do. You probably don’t like the default pattern. And you’ll certainly want to record your log events on files or databases, rather than the relatively ephemeral console.

Configuration is done outside your program by constructing a configuration file. This file can be a properties file, a JSON file, or another format, but we’ll demonstrate using an XML file. For log4j2 to find the file, it must be named “log4j2.xml” and must be on the execution classpath.

If you’re unfamiliar with XML, you can bone up with the tutorial at XML Overview.

In our demonstration project, the file (which is empty) is in a directory named “log4j”. Let’s add it to the execution classpath.

1. From the window menu, select Run/Run Configurations…. Select the configuration Main in the window on the left.
2. Click the Dependencies tab, then select Classpath Entries.
3. Click the Advanced button. Select Add Folders and click Ok.
4. Under Choose Folders to Add, select Lesson-17-Example-01/log4j. Click Ok.
5. In the Run Configurations window, click Apply.

Your configuration file can now be found.

Declaring an Appender and the Root Logger

So let’s put the following into the configuration file and save it:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="off" strict="true" name="XMLConfig"
               packages="org.apache.logging.log4j">

  <Appenders>
    <Appender type="Console" name="STDOUT">
      <Layout type="PatternLayout" pattern="[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n"/>
    </Appender>
  </Appenders>

  <Loggers>
    <Root level="debug">
      <AppenderRef ref="STDOUT"/>
    </Root>
  </Loggers>
 
</Configuration>

The name “STDOUT” is chosen by the developer.

status=”off” in the Configuration tag controls the logging level for events from the log4j2 configuration itself. We’ve set it to off.

The first section configures the appenders used by our loggers. Appenders determine where the output of the loggers is written–actually, appended, hence the name. In this case, we have one, named STDOUT. The tags describe it:

• Its type (Appender tag) is Console, meaning its output will be written to the console
• Its name (Appender tag) is STDOUT
• Its layout type (Layout tag) is PatternLayout
• The layout pattern (Layout tag) is “[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} – %msg%n”

There are many different kinds of appenders, including:

• File
• RollingFile
• JDBC (database)
• HTML
• OutputStream
• custom

For the complete lowdown, visit Log4j – Log4j 2 Appenders.

Now on to the logger definition. We have one: the root logger. The root logger is always present, and is at the top of the logger hierarchy. More on the hierarchy below.

We’ve configured our root logger to have a level of debug, and to have a single appender reference, to the appender we named STDOUT.

Now try running and the output looks like this:

[DEBUG] 2022-09-08 17:14:38.657 [main] FirstLogClass - This is a debug message from FirstLogClass
[INFO ] 2022-09-08 17:14:38.659 [main] FirstLogClass - This is an info message from FirstLogClass
[WARN ] 2022-09-08 17:14:38.660 [main] FirstLogClass - This is a warn message from FirstLogClass
[ERROR] 2022-09-08 17:14:38.660 [main] FirstLogClass - This is an error message from FirstLogClass
[FATAL] 2022-09-08 17:14:38.660 [main] FirstLogClass - This is a fatal message from FirstLogClass
[DEBUG] 2022-09-08 17:14:38.661 [main] SecondLogClass - This is a debug message from SecondLogClass
[INFO ] 2022-09-08 17:14:38.661 [main] SecondLogClass - This is an info message from SecondLogClass
[WARN ] 2022-09-08 17:14:38.661 [main] SecondLogClass - This is a warn message from SecondLogClass
[ERROR] 2022-09-08 17:14:38.661 [main] SecondLogClass - This is an error message from SecondLogClass
[FATAL] 2022-09-08 17:14:38.661 [main] SecondLogClass - This is a fatal message from SecondLogClass

Adding a Second Logger

Now suppose you want to see only logging messages from SecondLogClass with level WARN or higher. For this, you need a logger just for that class. So modify your configuration by adding the text in red:

  <Loggers>
    <Root level="debug">
      <AppenderRef ref="STDOUT"/>
    </Root>

    <Logger name="org.practicaljava.lesson16.exercise01.SecondLogClass" level="warn" additivity="false">
      <AppenderRef ref="STDOUT"/>
    </Logger>
  </Loggers>

What have we done here?

• We’ve added a new logger. The name of this new logger is the fully qualified name of the class SecondLogClass. It could be anything, but this is the name of the Logger that class SecondLogClass will get if it doesn’t specify a name–and by using that name, we’re indicating that this configuration pertains to that Logger.
• The logging level for this logger is warn.
• This logger will use appender STDOUT, just as the root logger does.
• The additivity property indicates that the event won’t be passed to loggers above this one in the hierarchy–in this case, the root logger. Without this, the root logger will repeat the logging event that gets through this logger, and the console will show the event once for this logger and again for the root logger (which also shows INFO, DEBUG, and TRACE events that this logger suppresses!).

The root logger also has a name: “”.

    LogManager.getLogger("mysharedlogger");

Run the job again and this time you’ll see this:

[DEBUG] 2022-09-09 15:21:47.775 [main] FirstLogClass - This is a debug message from FirstLogClass
[INFO ] 2022-09-09 15:21:47.778 [main] FirstLogClass - This is an info message from FirstLogClass
[WARN ] 2022-09-09 15:21:47.778 [main] FirstLogClass - This is a warn message from FirstLogClass
[ERROR] 2022-09-09 15:21:47.778 [main] FirstLogClass - This is an error message from FirstLogClass
[FATAL] 2022-09-09 15:21:47.778 [main] FirstLogClass - This is a fatal message from FirstLogClass
[WARN ] 2022-09-09 15:21:47.778 [main] SecondLogClass - This is a warn message from SecondLogClass
[ERROR] 2022-09-09 15:21:47.779 [main] SecondLogClass - This is an error message from SecondLogClass
[FATAL] 2022-09-09 15:21:47.779 [main] SecondLogClass - This is a fatal message from SecondLogClass

Notice that the only messages shown from SecondLogClass are of levels WARN, ERROR, and FATAL; messages at lower levels are filtered out.

This ability to modify the behavior of a particular logger is really useful if a class in your job–most likely provided by an outside supplier–puts out lots of useless log entries. You can specify properties for the logger, identified by the name the class is using (usually the class name itself), that suppress messages at the levels you don’t need to see. And as we said in the section on logger hierarchy, you can give the logger a name higher up in the hierarchy to control logging events in all classes in the same package.

Logging to Files

Now let’s write logs to files. For this, we’ll add a Property and two new appenders: one for an HTML file and one for a flat file. Add the lines in red to log4j2.xml:

<Configuration status="off" strict="true" name="XMLConfig"
               packages="org.apache.logging.log4j">
  <Properties>
    <Property name="directory">logs</Property>
  </Properties>

  <Appenders>
    <Appender type="Console" name="STDOUT">
      <Layout type="PatternLayout" pattern="[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n"/>
    </Appender>

    <Appender type="File" name="LOGFILE.LOG" fileName="${directory}/example01.log">
      <Layout type="PatternLayout">
        <Pattern>[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n</Pattern>
      </Layout>
    </Appender>

    <Appender type="File" name="LOGFILE.HTML" fileName="${directory}/example01.html" append="false">
      <Layout type="HtmlLayout">
        <Title>Messages from SecondLogClass</Title>
        <DatePattern>yyyy-MM-dd HH:mm:ss.SSS</DatePattern>
      </Layout>
    </Appender>
  </Appenders>

Here’s what we’ve done:

• The Property tag nested within the Properties tag (and which is optional) defines a property named directory and assigns it the value logs. We’ll use this property later.
• We define another new appender:
  • Its type is File.
  • Its name is LOGFILE.LOG.
  • The name of the file it will be written to is ${directory}/example01.log–but ${directory} gets replaced by the directory property we defined earlier, so the file name is actually logs/example01.html.
  • append is allowed to default, so each run will append to the existing file.
  • We specify the layout as PatternLayout and the pattern as the same used by the consoleapp appender.
• We define a second new appender:
  • Its type is File.
  • Its name is LOGFILE.HTML. (The name doesn’t require a period; we’ve just added it for readability.)
  • The name of the file it will be written to is logs/exercise01.html.
  • With append=false, we indicate the file will be erased and rewritten for each run.
  • We specify the layout is HTML.
  • The title of the resulting HTML page will be Messages From SecondLogClass.
  • The pattern of timestamps in the file is yyyy-MM-dd HH:mm:ss.SSS. The default pattern would be number of milliseconds from the start of the run.

Next we add tags that will let our loggers use these new appenders. The modifications are shown in red.

  <Loggers>
    <Root level="debug">
      <AppenderRef ref="STDOUT"/>
      <AppenderRef ref="LOGFILE.LOG"/>
      <AppenderRef ref="LOGFILE.HTML"/>
    </Root>

    <Logger name="org.practicaljava.lesson16.exercise01.SecondLogClass" level="warn" additivity="false">
      <AppenderRef ref="STDOUT"/>
      <AppenderRef ref="LOGFILE.LOG"/>
    </Logger>
  </Loggers>

What’s happening here?

• The root logger now has two additional appender references, to LOGFILE.HTML and LOGFILE.LOG, respectively. This means that the root logger (used only by FirstLogClass, remember) will write to the console, file example01.html, and example01.log.
• org…SecondLogClass (which is the logger used only by SecondLogClass) has an additional appender reference to LOGFILE.LOG. This means that this logger will write to the console and to example01.log–but not to example.html, because this logger doesn’t refer to the appropriate appender or propagate to the root logger (because additivity is false).

Now run the job again. To see the output files, you’ll need to select the project in the Package Explorer and press F5 (or select Refresh from a menu). You’ll see the logs directory within your project. Expand that and have a look at the logs.

In file example01.html, you’ll see log entries from FirstLogClass, but not from SecondLogClass because the former is the only one with a logger leading to the corresponding appender.

In file example01.log, you’ll see messages from both loggers, just as shown on the console, because both loggers address the appenders for both the console and for file example01.log.

If you run the program again, the log will repeat in example01.log because we let the appender’s append attribute default to true. But we set that property to false in the appender for example01.html, so the only thing that changes there is the timestamps.

Configuration With a Properties File

As mentioned above, the configuration file can be in any of a number of formats. For example, here’s equivalent of log4j2.xml in a properties file which, per the log4j specification, must be named log4j2.properties.

Place this in the same directory as log4j2.xml and rename the latter so log4j ignores it, and you’ll see much the same result when you run.

property.directory = logs

packages=org.practicaljava.lesson17.exercise01

appenders = consoleapp, file1, file2

appender.file1.type = File
appender.file1.name = LOGFILE.HTML
appender.file1.fileName=${directory}/example01.html
appender.file1.append=false
appender.file1.layout.type=HtmlLayout
appender.file1.layout.title=Messages From SecondLogClass
appender.file1.layout.datePattern = yyyy-MM-dd HH:mm:ss.SSS

appender.file2.type = File
appender.file2.name = LOGFILE.LOG
appender.file2.fileName=${directory}/example01.log
appender.file2.layout.type = PatternLayout
appender.file2.layout.pattern = [%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n

appender.consoleapp.type = Console
appender.consoleapp.name = STDOUT
appender.consoleapp.layout.type = PatternLayout
appender.consoleapp.layout.pattern = [%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} - %msg%n

rootLogger.level = debug
rootLogger.appenderRefs = charlie, logfilehtmlref, logfilelogref
rootLogger.appenderRef.charlie.ref = STDOUT
rootLogger.appenderRef.logfilehtmlref.ref = LOGFILE.HTML
rootLogger.appenderRef.logfilelogref.ref = LOGFILE.LOG

loggers=logclass2
logger.logclass2.name=org.practicaljava.lesson16.exercise01.SecondLogClass
logger.logclass2.level = warn
logger.logclass2.additivity = false
logger.logclass2.appenderRefs = logclass2ref, logfilelogref
logger.logclass2.appenderRef.logclass2ref.ref = STDOUT
logger.logclass2.appenderRef.logfilelogref.ref = LOGFILE.LOG

Each property setting in a properties file is of the form = property_name = property_value.

Why do we need to add names–charlie, logclass2, consoleapp–in our properties file that we didn’t need in XML. And why does, say, “consoleapp” appear in each of the property names in which it does? It’s because no property in a properties file is intrinsically related to any other (as opposed to XML, where any tag contained within another refers to the tag that contains it). log4j2 uses the appearance of “consoleapp” in each of the property names to establish that all these properties pertain to the consoleapp appender.

Because a configuration in XML is easier to configure, you’ll also find that most examples of configuration you’ll find on the Web are in XML.

Patterns

What do all those pattern characters mean? Here’s a summary of the most useful. For more details, visit the Apache web site here.

Each of these can be preceded (after the % sign) by optional modifiers:

• Left justification indicator: a minus sign.
• Minimum field width. Output is padded on the right (if the left justification indicator is present) or left (if not) with spaces to achieve the specified width.
• Maximum field with: a decimal value preceded by a period.

Creating Loggers in Java Code

Yes, you can create Loggers and Appenders (and modify them) in Java.

Why would you want to do this? Here’s an example from personal experience. In one shop, they ran a program which controlled other programs which were identifiable by name and a feed number. They needed a separate log file for each of the feeds (which often shared names), with a file name that would identify the source. It was impossible to configure a properties file for each possible feed. The solution was to create the loggers “on the fly.” Here’s a class showing how this can be accomplished.

/*****************************************************************************
 * This class returns a FileLogger with the name, file name,
 * level, and run number provided. 
 * An Appender and PatternLayout are attached to the Logger.
 * It modifies the Appender file name by appending
 * the run number and a timestamp.
 * 
 * Acknowledgements to Eugen Paraschiv for sample code from
 * which this class is adapted.
 */

import java.text.SimpleDateFormat;
import java.util.Date;

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.Appender;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.appender.FileAppender;
import org.apache.logging.log4j.core.config.AppenderRef;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.config.LoggerConfig;
import org.apache.logging.log4j.core.layout.PatternLayout;

public class PJLogger {

    // This overload lets the user pass a class whose name
    // becomes the logger name.
    public static Logger getLogger(Class<?> clazz, Level level, String pattern, String fileName, Integer runNumber) {
        String loggerName = clazz.getName();
        return getLogger(loggerName, level, pattern, fileName, runNumber);
    }

    // This overload lets the user default the name to the
    // name of the calling class.
    public static Logger getLogger(Level level, String pattern, String fileName, Integer runNumber) {
        StackTraceElement[] trace = Thread.currentThread().getStackTrace();
        
        // Search the trace for the name of this class, then
        // retain the element that follows.
        StackTraceElement caller = null;
        for (int index = 0; index < trace.length; index++) {
            StackTraceElement candidate = trace[index];
            if (candidate.getClassName().equals(PJLogger.class.getName())) {
                caller = trace[index + 1];
                break;
            }
        }
        String loggerName = caller.getClassName();
        return getLogger(loggerName, level, pattern, fileName, runNumber);
    }

    // Return a Logger.
    public static Logger getLogger(String loggerName, Level level, String pattern, String fileName, Integer runNumber) {
        LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
        Configuration config = ctx.getConfiguration();

        // If the Logger with the specified name already exists,
        // return it.
        {
            if (ctx.hasLogger(loggerName)) {
                return LogManager.getLogger(loggerName);
            }
        }

        // If no pattern has been provided, substitute a default.
        if (pattern == null) {
            pattern = "%d{yyyy-MM-dd HH:mm:ss} [%t] [%-5level] %c - %msg%n";
        }

        // Create the PatternLayout to use with the logger.
        PatternLayout layout = PatternLayout //
                .newBuilder() //
                .withConfiguration(config) //
                .withPattern(pattern) //
                .build();

        // Break off the file extension, append the run number and
        // current date/time to the rest, and reattach the extension
        // to get a final file name.
        int dotPos = fileName.lastIndexOf(".");
        StringBuilder fileNameBuf = new StringBuilder(fileName.substring(0, dotPos));
        SimpleDateFormat f = new SimpleDateFormat("yyyy-MM-dd-HH-mm-ss");
        fileNameBuf.append("_" + runNumber + "_" + f.format(new Date()));
        fileNameBuf.append(fileName.substring(dotPos));

        // Create the Appender with the modified file name.
        // The Appender's name is the logger name followed
        // by ".Appender".
        // The appender will append to an existing file
        // on the off chance that one exists with the same
        // filename.
        String appenderName = loggerName + ".Appender";
        Appender appender = FileAppender //
                .newBuilder() //
                .setConfiguration(config) //
                .setName(appenderName) //
                .setLayout(layout) //
                .withFileName(fileNameBuf.toString()) //
                .withAppend(true) //
                .build();

        // Start the Appender and add it to the configuration.
        appender.start();
        config.addAppender(appender);

        // Create an AppenderRef with the same name as the
        // Appender, and an array containing only it.
        AppenderRef ref = AppenderRef.createAppenderRef(appender.getName(), null, null);
        AppenderRef[] refs = new AppenderRef[] { ref };

        // Create a LoggerConfig with the requested logger name and
        // the array of AppenderRefs (which has only one element,
        // of course).
        LoggerConfig loggerConfig = LoggerConfig.createLogger(false, level, loggerName, "true", refs, null, config,
                null);

        // Add our Appender and Logger to the system
        // configuration, then inform the LoggerContext
        // that the configuration has changed.
        loggerConfig.addAppender(appender, null, null);
        config.addLogger(loggerName, loggerConfig);
        ctx.updateLoggers();

        return LogManager.getLogger(loggerName);
    }
}

And here’s a class that uses a logger created by PJLogger.getLogger().

public class LogDriver {
    public static void main(String[] args) {
        Logger logger = PJLogger.getLogger("myLogger", Level.INFO, null, "logs/newLog.log", 45);
        logger.info("This is the message.");
    }
}

What You Need To Know

Next: Properties