SLF4J Logging Levels Example

Rajagopal ParthaSarathiNovember 2nd, 2018Last Updated: October 29th, 2018

1 3,036 6 minutes read

This post is about the various logging levels available in SLF4J and how to extend it with Marker interface. This post utilizes Logback as the logging implementation for our examples.

1. SLF4J Tutorial – Introduction

Before jumping into SLF4J, we will take a short look at the reason for its existence. Logging is an important aspect of any application. It can help troubleshoot common issues within our application. It can also allow gain insights into the performance of our application. In the current landscape, there are a lot of logging frameworks available which fulfills all our application’s needs. Each one comes with its own set of pros and cons. Each logging framework can handle certain needs and switching the logging framework should not be painful.

The Simple Logging Facade for Java (SLF4J) is an abstraction over the various logging frameworks available for Java. It provides a simple interface which will be implemented by the logging frameworks in existence. The beauty of SLF4J is that it allows end users to plug in their logging framework of choice during deployment time. Developers just need to include the logging framework dependency in the classpath and SLF4J will utilize it to append the logs. If no logging dependency is provided on the classpath, it will default to a no-operation implementation and nothing gets logged.

2. SLF4J Logging Levels

We will see the various levels of SLF4J with examples. We will cover an application highlighting the various log levels. The application is developed as Maven project and we will cover the Maven Configuration first

pom.xml

<?xml version="1.0" encoding="UTF-8"?>
<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>com.jcg</groupId>
    <artifactId>slf4j</artifactId>
    <version>1.0-SNAPSHOT</version>

    <dependencies>
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>1.2.3</version>
            <scope>runtime</scope>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.25</version>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-compiler-plugin</artifactId>
                <version>3.6.1</version>
                <configuration>
                    <source>1.8</source>
                    <target>1.8</target>
                </configuration>
            </plugin>
        </plugins>
    </build>

</project>

We have specified our artifact as SLF4J in line 8.
We specify slf4j-api as a dependency in lines 13-15. Maven downloads the SLF4J dependency in our classpath to enable the logging interface.
We provide Java8 as the target compiler for our application.
We have defined logback as the runtime dependency.

We will cover logback configuration to output the logs to the console.

logback.xml

<configuration>

    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <target>System.out</target>
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %msg%n</pattern>
        </encoder>
    </appender>

    <root level="error">
        <appender-ref ref="console"/>
    </root>

</configuration>

We specify an appender name and provide the class as ConsoleAppender
As the name indicates, it supports two targets – System.Out or System.err and we have specified output console
We have supplied the pattern %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} %msg%n and encoder is set to PatternLayoutEncoder by default.
- The pattern indicates the date for d followed by the pattern which is to get the current time till milliseconds.
- thread indicates the currently executing thread
- level indicates the logging level upto 5 characters in length
- logger indicates the logger name(mostly logger class) upto 36 characters in length
- msg is the actual message supplied to the logger
- n is the system line separator
In Lines 10-12, We wire up the appender to our root logger with logging level set to error.

We will cover our application use below.

LoggerRoot.java

package com.jcg;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;

import java.lang.invoke.MethodHandles;

public class LoggerRoot {

    private static final Logger logger = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass().getSimpleName());

    public static void main(String[] args) {
        logger.info("Running the sequence");
        runLoop(1);
        runLoop(0);
        logger.info("Sequence completed");

    }

    public static void runLoop(int number) {
        logger.trace("Run loop started");
         if(number == 0){
            logger.warn("Number:{}",number);
        }
        for (int token = 1; token <= 10; token++) {
            logger.debug("loop number" + token);
            logger.trace("Running the division application");
            try {
                int quotient = token / number;
                logger.trace("Quotient is" + quotient);
            } catch (Exception e) {
                logger.error("Exception in runLoop", e);
                break;
            }
        }
        logger.trace("Run loop exited");
    }
}

We have defined a simple method runLoop which runs the loop from 1 to 10 and divides each one by the number specified as input to the function.
We have added logs throughout this method to demonstrate the various logging levels.

Running the above example produces the following output

08:05:59.877 [main] ERROR LoggerRoot Exception in runLoop
java.lang.ArithmeticException: / by zero
	at com.jcg.LoggerRoot.runLoop(LoggerRoot.java:30)
	at com.jcg.LoggerRoot.main(LoggerRoot.java:17)

Error Mode is the default mode in most of the production use cases. This helps in identifying an error has occurred and provides some basic information. Logging incurs a performance cost and it is recommended to keep logs to the minimum in production. As soon as the issue is to be debugged in lower environments, the other log levels help.

Firstly, We should enable WARN level to identify warning scenarios. This is the next level in Hierarchy. The only change is to enable <root level="warn">. Running the application produces the following output

08:28:32.621 [main]  WARN  LoggerRoot Number:0
08:05:59.877 [main] ERROR LoggerRoot Exception in runLoop
java.lang.ArithmeticException: / by zero
	at com.jcg.LoggerRoot.runLoop(LoggerRoot.java:30)
	at com.jcg.LoggerRoot.main(LoggerRoot.java:17)

This generates a warning message of number zero. This hints the potential reason for failure. Now comes the next log level INFO. The only change is to enable <root level="info">. This ensures that the application provides informational log messages. Now running the application produces the following output.

08:32:34.561 [main]  INFO  LoggerRoot Running the sequence
08:32:34.561 [main]  WARN  LoggerRoot Number:0
08:32:34.577 [main] ERROR LoggerRoot Exception in runLoop
java.lang.ArithmeticException: / by zero
	at com.jcg.LoggerRoot.runLoop(LoggerRoot.java:32)
	at com.jcg.LoggerRoot.main(LoggerRoot.java:17)
08:32:34.577 [main]  INFO  LoggerRoot Sequence completed

Now, this pinpoints the method being run and would be able to fix the issue. There are two more log levels provided further for specific use cases. DEBUG is generally used to provide debugging messages and generally helps debug in case of such issues. TRACE is used to provide general messages to trace the application flow. To enable the application to provide all flows, the log configuration needs to be set as <root level="trace">.

08:39:13.748 [main]  INFO  LoggerRoot Running the sequence
08:39:13.748 [main]  TRACE LoggerRoot Run loop started
08:39:13.748 [main]  DEBUG LoggerRoot loop number1
08:39:13.748 [main]  TRACE LoggerRoot Running the division application
08:39:13.748 [main]  TRACE LoggerRoot Quotient is1
08:39:13.748 [main]  DEBUG LoggerRoot loop number2
08:39:13.748 [main]  TRACE LoggerRoot Running the division application
08:39:13.748 [main]  TRACE LoggerRoot Quotient is2
08:39:13.748 [main]  DEBUG LoggerRoot loop number3
08:39:13.748 [main]  TRACE LoggerRoot Running the division application
08:39:13.748 [main]  TRACE LoggerRoot Quotient is3
08:39:13.748 [main]  DEBUG LoggerRoot loop number4
08:39:13.748 [main]  TRACE LoggerRoot Running the division application
08:39:13.748 [main]  TRACE LoggerRoot Quotient is4
08:39:13.748 [main]  DEBUG LoggerRoot loop number5
08:39:13.748 [main]  TRACE LoggerRoot Running the division application
08:39:13.748 [main]  TRACE LoggerRoot Quotient is5
08:39:13.748 [main]  DEBUG LoggerRoot loop number6
08:39:13.748 [main]  TRACE LoggerRoot Running the division application
08:39:13.748 [main]  TRACE LoggerRoot Quotient is6
08:39:13.748 [main]  DEBUG LoggerRoot loop number7
08:39:13.748 [main]  TRACE LoggerRoot Running the division application
08:39:13.748 [main]  TRACE LoggerRoot Quotient is7
08:39:13.748 [main]  DEBUG LoggerRoot loop number8
08:39:13.748 [main]  TRACE LoggerRoot Running the division application
08:39:13.748 [main]  TRACE LoggerRoot Quotient is8
08:39:13.748 [main]  DEBUG LoggerRoot loop number9
08:39:13.748 [main]  TRACE LoggerRoot Running the division application
08:39:13.748 [main]  TRACE LoggerRoot Quotient is9
08:39:13.748 [main]  DEBUG LoggerRoot loop number10
08:39:13.748 [main]  TRACE LoggerRoot Running the division application
08:39:13.748 [main]  TRACE LoggerRoot Quotient is10
08:39:13.748 [main]  TRACE LoggerRoot Run loop exited
08:39:13.748 [main]  TRACE LoggerRoot Run loop started
08:39:13.764 [main]  WARN  LoggerRoot Number:0
08:39:13.764 [main]  DEBUG LoggerRoot loop number1
08:39:13.764 [main]  TRACE LoggerRoot Running the division application
08:39:13.764 [main] ERROR LoggerRoot Exception in runLoop
java.lang.ArithmeticException: / by zero
	at com.jcg.LoggerRoot.runLoop(LoggerRoot.java:32)
	at com.jcg.LoggerRoot.main(LoggerRoot.java:17)
08:39:13.764 [main]  TRACE LoggerRoot Run loop exited
08:39:13.764 [main]  INFO  LoggerRoot Sequence completed

This provides comprehensive information on our application execution. This covers the existing logging levels available in SLF4J. In the next section, We will take a look at a way to extend for additional levels.

2.1 Marker Interface

Suppose, We wanted to mark the exception in the previous example as FATAL. SLF4J provides the Marker interface to mark additional levels. We have to define the additional level in our application.

LoggerRoot.java

Marker fatal = MarkerFactory.getMarker("FATAL");
...
logger.error(fatal, "Exception in runLoop", e);

In the first line, We are defining a new level of FATAL using MarkerFactory.
We use the created level and affix our log with that in the second line.

logback.xml

...
<pattern>%d{HH:mm:ss.SSS} [%thread] %marker %-5level %logger{36} %msg%n</pattern>
...

We add %marker to the pattern so the created level will be displayed in the log messages. Running the above example produces the following output

08:39:13.764 [main] FATAL ERROR LoggerRoot Exception in runLoop
java.lang.ArithmeticException: / by zero
	at com.jcg.LoggerRoot.runLoop(LoggerRoot.java:32)
	at com.jcg.LoggerRoot.main(LoggerRoot.java:17)

The newly added level FATAL is displayed in the log messages and We could add it to any of the existing log messages.